logging: use lazy parameter evaluation in log calls.
marcink -
r3061:a44afbe5 default
Not Reviewed
Show More
Add another comment
TODOs: 0 unresolved 0 Resolved
COMMENTS: 0 General 0 Inline
@@ -204,7 +204,7
204 message='Request from IP:%s not allowed' % (
204 message='Request from IP:%s not allowed' % (
205 request.rpc_ip_addr,))
205 request.rpc_ip_addr,))
206 else:
206 else:
207 log.info('Access for IP:%s allowed' % (request.rpc_ip_addr,))
207 log.info('Access for IP:%s allowed', request.rpc_ip_addr)
208
208
209 # register our auth-user
209 # register our auth-user
210 request.rpc_user = auth_u
210 request.rpc_user = auth_u
@@ -352,8 +352,7
352 request.rpc_params = json_body['args'] \
352 request.rpc_params = json_body['args'] \
353 if isinstance(json_body['args'], dict) else {}
353 if isinstance(json_body['args'], dict) else {}
354
354
355 log.debug(
355 log.debug('method: %s, params: %s', request.rpc_method, request.rpc_params)
356 'method: %s, params: %s' % (request.rpc_method, request.rpc_params))
357 except KeyError as e:
356 except KeyError as e:
358 raise JSONRPCError('Incorrect JSON data. Missing %s' % e)
357 raise JSONRPCError('Incorrect JSON data. Missing %s' % e)
359
358
@@ -405,8 +405,8
405 revision = self.request.GET.get('revision')
405 revision = self.request.GET.get('revision')
406
406
407 if revision != last_rev.raw_id:
407 if revision != last_rev.raw_id:
408 log.error('Last revision %s is different then submitted %s'
408 log.error('Last revision %s is different then submitted %s',
409 % (revision, last_rev))
409 revision, last_rev)
410 # our gist has newer version than we
410 # our gist has newer version than we
411 success = False
411 success = False
412
412
@@ -93,16 +93,16
93 allowed_schemes = ['http', 'https']
93 allowed_schemes = ['http', 'https']
94 default_came_from = h.route_path('home')
94 default_came_from = h.route_path('home')
95 if parsed.scheme and parsed.scheme not in allowed_schemes:
95 if parsed.scheme and parsed.scheme not in allowed_schemes:
96 log.error('Suspicious URL scheme detected %s for url %s' %
96 log.error('Suspicious URL scheme detected %s for url %s',
97 (parsed.scheme, parsed))
97 parsed.scheme, parsed)
98 came_from = default_came_from
98 came_from = default_came_from
99 elif parsed.netloc and request.host != parsed.netloc:
99 elif parsed.netloc and request.host != parsed.netloc:
100 log.error('Suspicious NETLOC detected %s for url %s server url '
100 log.error('Suspicious NETLOC detected %s for url %s server url '
101 'is: %s' % (parsed.netloc, parsed, request.host))
101 'is: %s', parsed.netloc, parsed, request.host)
102 came_from = default_came_from
102 came_from = default_came_from
103 elif any(bad_str in parsed.path for bad_str in ('\r', '\n')):
103 elif any(bad_str in parsed.path for bad_str in ('\r', '\n')):
104 log.error('Header injection detected `%s` for url %s server url ' %
104 log.error('Header injection detected `%s` for url %s server url ',
105 (parsed.path, parsed))
105 parsed.path, parsed)
106 came_from = default_came_from
106 came_from = default_came_from
107
107
108 return came_from or default_came_from
108 return came_from or default_came_from
@@ -256,8 +256,8
256 # case we want a simple diff without incoming commits,
256 # case we want a simple diff without incoming commits,
257 # previewing what will be merged.
257 # previewing what will be merged.
258 # Make the diff on target repo (which is known to have target_ref)
258 # Make the diff on target repo (which is known to have target_ref)
259 log.debug('Using ancestor %s as source_ref instead of %s'
259 log.debug('Using ancestor %s as source_ref instead of %s',
260 % (c.ancestor, source_ref))
260 c.ancestor, source_ref)
261 source_repo = target_repo
261 source_repo = target_repo
262 source_commit = target_repo.get_commit(commit_id=c.ancestor)
262 source_commit = target_repo.get_commit(commit_id=c.ancestor)
263
263
@@ -98,8 +98,8
98 ScmModel().strip(
98 ScmModel().strip(
99 repo=self.db_repo,
99 repo=self.db_repo,
100 commit_id=commit['rev'], branch=commit['branch'])
100 commit_id=commit['rev'], branch=commit['branch'])
101 log.info('Stripped commit %s from repo `%s` by %s' % (
101 log.info('Stripped commit %s from repo `%s` by %s',
102 commit['rev'], self.db_repo_name, user))
102 commit['rev'], self.db_repo_name, user)
103 data[commit['rev']] = True
103 data[commit['rev']] = True
104
104
105 audit_logger.store_web(
105 audit_logger.store_web(
@@ -108,6 +108,6
108
108
109 except Exception as e:
109 except Exception as e:
110 data[commit['rev']] = False
110 data[commit['rev']] = False
111 log.debug('Stripped commit %s from repo `%s` failed by %s, exeption %s' % (
111 log.debug('Stripped commit %s from repo `%s` failed by %s, exeption %s',
112 commit['rev'], self.db_repo_name, user, e.message))
112 commit['rev'], self.db_repo_name, user, e.message)
113 return data
113 return data
@@ -241,16 +241,16
241 log.debug('Empty username or password skipping...')
241 log.debug('Empty username or password skipping...')
242 return None
242 return None
243
243
244 log.debug("Crowd settings: \n%s" % (formatted_json(settings)))
244 log.debug("Crowd settings: \n%s", formatted_json(settings))
245 server = CrowdServer(**settings)
245 server = CrowdServer(**settings)
246 server.set_credentials(settings["app_name"], settings["app_password"])
246 server.set_credentials(settings["app_name"], settings["app_password"])
247 crowd_user = server.user_auth(username, password)
247 crowd_user = server.user_auth(username, password)
248 log.debug("Crowd returned: \n%s" % (formatted_json(crowd_user)))
248 log.debug("Crowd returned: \n%s", formatted_json(crowd_user))
249 if not crowd_user["status"]:
249 if not crowd_user["status"]:
250 return None
250 return None
251
251
252 res = server.user_groups(crowd_user["name"])
252 res = server.user_groups(crowd_user["name"])
253 log.debug("Crowd groups: \n%s" % (formatted_json(res)))
253 log.debug("Crowd groups: \n%s", formatted_json(res))
254 crowd_user["groups"] = [x["name"] for x in res["groups"]]
254 crowd_user["groups"] = [x["name"] for x in res["groups"]]
255
255
256 # old attrs fetched from RhodeCode database
256 # old attrs fetched from RhodeCode database
@@ -280,6 +280,6
280 for group in settings["admin_groups"]:
280 for group in settings["admin_groups"]:
281 if group in user_attrs["groups"]:
281 if group in user_attrs["groups"]:
282 user_attrs["admin"] = True
282 user_attrs["admin"] = True
283 log.debug("Final crowd user object: \n%s" % (formatted_json(user_attrs)))
283 log.debug("Final crowd user object: \n%s", formatted_json(user_attrs))
284 log.info('user `%s` authenticated correctly' % user_attrs['username'])
284 log.info('user `%s` authenticated correctly', user_attrs['username'])
285 return user_attrs
285 return user_attrs
@@ -125,24 +125,24
125 username = None
125 username = None
126 environ = environ or {}
126 environ = environ or {}
127 if not environ:
127 if not environ:
128 log.debug('got empty environ: %s' % environ)
128 log.debug('got empty environ: %s', environ)
129
129
130 settings = settings or {}
130 settings = settings or {}
131 if settings.get('header'):
131 if settings.get('header'):
132 header = settings.get('header')
132 header = settings.get('header')
133 username = environ.get(header)
133 username = environ.get(header)
134 log.debug('extracted %s:%s' % (header, username))
134 log.debug('extracted %s:%s', header, username)
135
135
136 # fallback mode
136 # fallback mode
137 if not username and settings.get('fallback_header'):
137 if not username and settings.get('fallback_header'):
138 header = settings.get('fallback_header')
138 header = settings.get('fallback_header')
139 username = environ.get(header)
139 username = environ.get(header)
140 log.debug('extracted %s:%s' % (header, username))
140 log.debug('extracted %s:%s', header, username)
141
141
142 if username and str2bool(settings.get('clean_username')):
142 if username and str2bool(settings.get('clean_username')):
143 log.debug('Received username `%s` from headers' % username)
143 log.debug('Received username `%s` from headers', username)
144 username = self._clean_username(username)
144 username = self._clean_username(username)
145 log.debug('New cleanup user is:%s' % username)
145 log.debug('New cleanup user is:%s', username)
146 return username
146 return username
147
147
148 def get_user(self, username=None, **kwargs):
148 def get_user(self, username=None, **kwargs):
@@ -221,5 +221,5
221 'extern_type': extern_type,
221 'extern_type': extern_type,
222 }
222 }
223
223
224 log.info('user `%s` authenticated correctly' % user_attrs['username'])
224 log.info('user `%s` authenticated correctly', user_attrs['username'])
225 return user_attrs
225 return user_attrs
@@ -134,10 +134,10
134 try:
134 try:
135 response = urllib2.urlopen(request)
135 response = urllib2.urlopen(request)
136 except urllib2.HTTPError as e:
136 except urllib2.HTTPError as e:
137 log.debug("HTTPError when requesting Jasig CAS (status code: %d)" % e.code)
137 log.debug("HTTPError when requesting Jasig CAS (status code: %d)", e.code)
138 return None
138 return None
139 except urllib2.URLError as e:
139 except urllib2.URLError as e:
140 log.debug("URLError when requesting Jasig CAS url: %s " % url)
140 log.debug("URLError when requesting Jasig CAS url: %s ", url)
141 return None
141 return None
142
142
143 # old attrs fetched from RhodeCode database
143 # old attrs fetched from RhodeCode database
@@ -163,5 +163,5
163 'extern_type': extern_type,
163 'extern_type': extern_type,
164 }
164 }
165
165
166 log.info('user `%s` authenticated correctly' % user_attrs['username'])
166 log.info('user `%s` authenticated correctly', user_attrs['username'])
167 return user_attrs
167 return user_attrs
@@ -115,10 +115,10
115 auth_result = _pam.authenticate(username, password, settings["service"])
115 auth_result = _pam.authenticate(username, password, settings["service"])
116
116
117 if not auth_result:
117 if not auth_result:
118 log.error("PAM was unable to authenticate user: %s" % (username, ))
118 log.error("PAM was unable to authenticate user: %s", username)
119 return None
119 return None
120
120
121 log.debug('Got PAM response %s' % (auth_result, ))
121 log.debug('Got PAM response %s', auth_result)
122
122
123 # old attrs fetched from RhodeCode database
123 # old attrs fetched from RhodeCode database
124 default_email = "%s@%s" % (username, socket.gethostname())
124 default_email = "%s@%s" % (username, socket.gethostname())
@@ -157,5 +157,5
157 pass
157 pass
158
158
159 log.debug("pamuser: %s", user_attrs)
159 log.debug("pamuser: %s", user_attrs)
160 log.info('user `%s` authenticated correctly' % user_attrs['username'])
160 log.info('user `%s` authenticated correctly', user_attrs['username'])
161 return user_attrs
161 return user_attrs
@@ -87,12 +87,12
87
87
88 def auth(self, userobj, username, password, settings, **kwargs):
88 def auth(self, userobj, username, password, settings, **kwargs):
89 if not userobj:
89 if not userobj:
90 log.debug('userobj was:%s skipping' % (userobj, ))
90 log.debug('userobj was:%s skipping', userobj)
91 return None
91 return None
92 if userobj.extern_type != self.name:
92 if userobj.extern_type != self.name:
93 log.warning(
93 log.warning(
94 "userobj:%s extern_type mismatch got:`%s` expected:`%s`" %
94 "userobj:%s extern_type mismatch got:`%s` expected:`%s`",
95 (userobj, userobj.extern_type, self.name))
95 userobj, userobj.extern_type, self.name)
96 return None
96 return None
97
97
98 user_attrs = {
98 user_attrs = {
@@ -109,7 +109,7
109 "extern_type": userobj.extern_type,
109 "extern_type": userobj.extern_type,
110 }
110 }
111
111
112 log.debug("User attributes:%s" % (user_attrs, ))
112 log.debug("User attributes:%s", user_attrs)
113 if userobj.active:
113 if userobj.active:
114 from rhodecode.lib import auth
114 from rhodecode.lib import auth
115 crypto_backend = auth.crypto_backend()
115 crypto_backend = auth.crypto_backend()
@@ -103,7 +103,7
103
103
104 def auth(self, userobj, username, password, settings, **kwargs):
104 def auth(self, userobj, username, password, settings, **kwargs):
105 if not userobj:
105 if not userobj:
106 log.debug('userobj was:%s skipping' % (userobj, ))
106 log.debug('userobj was:%s skipping', userobj)
107 return None
107 return None
108
108
109 user_attrs = {
109 user_attrs = {
@@ -133,7 +133,7
133 missing_commits = set(commit_ids) - set(c['raw_id'] for c in commits)
133 missing_commits = set(commit_ids) - set(c['raw_id'] for c in commits)
134 if missing_commits:
134 if missing_commits:
135 log.error('Inconsistent repository state. '
135 log.error('Inconsistent repository state. '
136 'Missing commits: %s' % ', '.join(missing_commits))
136 'Missing commits: %s', ', '.join(missing_commits))
137
137
138 return commits
138 return commits
139
139
@@ -66,8 +66,8
66 exc_info = sys.exc_info()
66 exc_info = sys.exc_info()
67 store_exception(id(exc_info), exc_info)
67 store_exception(id(exc_info), exc_info)
68 log.exception(
68 log.exception(
69 'failure occurred when sending event %s to integration %s' % (
69 'failure occurred when sending event %s to integration %s',
70 event, integration))
70 event, integration)
71
71
72
72
73 def includeme(config):
73 def includeme(config):
@@ -31,8 +31,7
31 key = IntegrationType.key
31 key = IntegrationType.key
32 if key in self:
32 if key in self:
33 log.debug(
33 log.debug(
34 'Overriding existing integration type %s (%s) with %s' % (
34 'Overriding existing integration type %s (%s) with %s',
35 self[key], key, IntegrationType))
35 self[key], key, IntegrationType)
36
36
37 self[key] = IntegrationType
37 self[key] = IntegrationType
38
@@ -119,11 +119,11
119
119
120 def send_event(self, event):
120 def send_event(self, event):
121 if event.__class__ not in self.valid_events:
121 if event.__class__ not in self.valid_events:
122 log.debug('event not valid: %r' % event)
122 log.debug('event not valid: %r', event)
123 return
123 return
124
124
125 if event.name not in self.settings['events']:
125 if event.name not in self.settings['events']:
126 log.debug('event ignored: %r' % event)
126 log.debug('event ignored: %r', event)
127 return
127 return
128
128
129 data = event.as_dict()
129 data = event.as_dict()
@@ -131,7 +131,7
131 text = '<b>%s<b> caused a <b>%s</b> event' % (
131 text = '<b>%s<b> caused a <b>%s</b> event' % (
132 data['actor']['username'], event.name)
132 data['actor']['username'], event.name)
133
133
134 log.debug('handling hipchat event for %s' % event.name)
134 log.debug('handling hipchat event for %s', event.name)
135
135
136 if isinstance(event, events.PullRequestCommentEvent):
136 if isinstance(event, events.PullRequestCommentEvent):
137 text = self.format_pull_request_comment_event(event, data)
137 text = self.format_pull_request_comment_event(event, data)
@@ -144,7 +144,7
144 elif isinstance(event, events.RepoCreateEvent):
144 elif isinstance(event, events.RepoCreateEvent):
145 text = self.format_repo_create_event(data)
145 text = self.format_repo_create_event(data)
146 else:
146 else:
147 log.error('unhandled event type: %r' % event)
147 log.error('unhandled event type: %r', event)
148
148
149 run_task(post_text_to_hipchat, self.settings, text)
149 run_task(post_text_to_hipchat, self.settings, text)
150
150
@@ -242,7 +242,7
242
242
243 @async_task(ignore_result=True, base=RequestContextTask)
243 @async_task(ignore_result=True, base=RequestContextTask)
244 def post_text_to_hipchat(settings, text):
244 def post_text_to_hipchat(settings, text):
245 log.debug('sending %s to hipchat %s' % (text, settings['server_url']))
245 log.debug('sending %s to hipchat %s', text, settings['server_url'])
246 json_message = {
246 json_message = {
247 "message": text,
247 "message": text,
248 "color": settings.get('color', 'yellow'),
248 "color": settings.get('color', 'yellow'),
@@ -110,11 +110,11
110
110
111 def send_event(self, event):
111 def send_event(self, event):
112 if event.__class__ not in self.valid_events:
112 if event.__class__ not in self.valid_events:
113 log.debug('event not valid: %r' % event)
113 log.debug('event not valid: %r', event)
114 return
114 return
115
115
116 if event.name not in self.settings['events']:
116 if event.name not in self.settings['events']:
117 log.debug('event ignored: %r' % event)
117 log.debug('event ignored: %r', event)
118 return
118 return
119
119
120 data = event.as_dict()
120 data = event.as_dict()
@@ -127,7 +127,7
127 fields = None
127 fields = None
128 overrides = None
128 overrides = None
129
129
130 log.debug('handling slack event for %s' % event.name)
130 log.debug('handling slack event for %s', event.name)
131
131
132 if isinstance(event, events.PullRequestCommentEvent):
132 if isinstance(event, events.PullRequestCommentEvent):
133 (title, text, fields, overrides) \
133 (title, text, fields, overrides) \
@@ -141,7 +141,7
141 elif isinstance(event, events.RepoCreateEvent):
141 elif isinstance(event, events.RepoCreateEvent):
142 title, text = self.format_repo_create_event(data)
142 title, text = self.format_repo_create_event(data)
143 else:
143 else:
144 log.error('unhandled event type: %r' % event)
144 log.error('unhandled event type: %r', event)
145
145
146 run_task(post_text_to_slack, self.settings, title, text, fields, overrides)
146 run_task(post_text_to_slack, self.settings, title, text, fields, overrides)
147
147
@@ -314,8 +314,7
314
314
315 @async_task(ignore_result=True, base=RequestContextTask)
315 @async_task(ignore_result=True, base=RequestContextTask)
316 def post_text_to_slack(settings, title, text, fields=None, overrides=None):
316 def post_text_to_slack(settings, title, text, fields=None, overrides=None):
317 log.debug('sending %s (%s) to slack %s' % (
317 log.debug('sending %s (%s) to slack %s', title, text, settings['service'])
318 title, text, settings['service']))
319
318
320 fields = fields or []
319 fields = fields or []
321 overrides = overrides or {}
320 overrides = overrides or {}
@@ -171,11 +171,11
171 'handling event %s with Webhook integration %s', event.name, self)
171 'handling event %s with Webhook integration %s', event.name, self)
172
172
173 if event.__class__ not in self.valid_events:
173 if event.__class__ not in self.valid_events:
174 log.debug('event not valid: %r' % event)
174 log.debug('event not valid: %r', event)
175 return
175 return
176
176
177 if event.name not in self.settings['events']:
177 if event.name not in self.settings['events']:
178 log.debug('event ignored: %r' % event)
178 log.debug('event ignored: %r', event)
179 return
179 return
180
180
181 data = event.as_dict()
181 data = event.as_dict()
@@ -979,7 +979,7
979 }
979 }
980
980
981 log.debug(
981 log.debug(
982 'Allowed views for AUTH TOKEN access: %s' % (whitelist,))
982 'Allowed views for AUTH TOKEN access: %s', whitelist)
983 auth_token_access_valid = False
983 auth_token_access_valid = False
984
984
985 for entry in whitelist:
985 for entry in whitelist:
@@ -998,8 +998,9
998 break
998 break
999
999
1000 if auth_token_access_valid:
1000 if auth_token_access_valid:
1001 log.debug('view: `%s` matches entry in whitelist: %s'
1001 log.debug('view: `%s` matches entry in whitelist: %s',
1002 % (view_name, whitelist))
1002 view_name, whitelist)
1003
1003 else:
1004 else:
1004 msg = ('view: `%s` does *NOT* match any entry in whitelist: %s'
1005 msg = ('view: `%s` does *NOT* match any entry in whitelist: %s'
1005 % (view_name, whitelist))
1006 % (view_name, whitelist))
@@ -1190,7 +1191,7
1190
1191
1191 log.debug(
1192 log.debug(
1192 'Computing PERMISSION tree for user %s scope `%s` '
1193 'Computing PERMISSION tree for user %s scope `%s` '
1193 'with caching: %s[TTL: %ss]' % (user, scope, cache_on, cache_seconds or 0))
1194 'with caching: %s[TTL: %ss]', user, scope, cache_on, cache_seconds or 0)
1194
1195
1195 cache_namespace_uid = 'cache_user_auth.{}'.format(user_id)
1196 cache_namespace_uid = 'cache_user_auth.{}'.format(user_id)
1196 region = rc_cache.get_or_create_region('cache_perms', cache_namespace_uid)
1197 region = rc_cache.get_or_create_region('cache_perms', cache_namespace_uid)
@@ -1214,8 +1215,8
1214 for k in result:
1215 for k in result:
1215 result_repr.append((k, len(result[k])))
1216 result_repr.append((k, len(result[k])))
1216 total = time.time() - start
1217 total = time.time() - start
1217 log.debug('PERMISSION tree for user %s computed in %.3fs: %s' % (
1218 log.debug('PERMISSION tree for user %s computed in %.3fs: %s',
1218 user, total, result_repr))
1219 user, total, result_repr)
1219
1220
1220 return result
1221 return result
1221
1222
@@ -1352,12 +1353,12
1352 allowed_ips = AuthUser.get_allowed_ips(
1353 allowed_ips = AuthUser.get_allowed_ips(
1353 user_id, cache=True, inherit_from_default=inherit_from_default)
1354 user_id, cache=True, inherit_from_default=inherit_from_default)
1354 if check_ip_access(source_ip=ip_addr, allowed_ips=allowed_ips):
1355 if check_ip_access(source_ip=ip_addr, allowed_ips=allowed_ips):
1355 log.debug('IP:%s for user %s is in range of %s' % (
1356 log.debug('IP:%s for user %s is in range of %s',
1356 ip_addr, user_id, allowed_ips))
1357 ip_addr, user_id, allowed_ips)
1357 return True
1358 return True
1358 else:
1359 else:
1359 log.info('Access for IP:%s forbidden for user %s, '
1360 log.info('Access for IP:%s forbidden for user %s, '
1360 'not in %s' % (ip_addr, user_id, allowed_ips))
1361 'not in %s', ip_addr, user_id, allowed_ips)
1361 return False
1362 return False
1362
1363
1363 def get_branch_permissions(self, repo_name, perms=None):
1364 def get_branch_permissions(self, repo_name, perms=None):
@@ -1593,7 +1594,7
1593 _ = request.translate
1594 _ = request.translate
1594
1595
1595 loc = "%s:%s" % (cls.__class__.__name__, func.__name__)
1596 loc = "%s:%s" % (cls.__class__.__name__, func.__name__)
1596 log.debug('Starting login restriction checks for user: %s' % (user,))
1597 log.debug('Starting login restriction checks for user: %s', user)
1597 # check if our IP is allowed
1598 # check if our IP is allowed
1598 ip_access_valid = True
1599 ip_access_valid = True
1599 if not user.ip_allowed:
1600 if not user.ip_allowed:
@@ -1610,7 +1611,7
1610
1611
1611 # explicit controller is enabled or API is in our whitelist
1612 # explicit controller is enabled or API is in our whitelist
1612 if self.auth_token_access or auth_token_access_valid:
1613 if self.auth_token_access or auth_token_access_valid:
1613 log.debug('Checking AUTH TOKEN access for %s' % (cls,))
1614 log.debug('Checking AUTH TOKEN access for %s', cls)
1614 db_user = user.get_instance()
1615 db_user = user.get_instance()
1615
1616
1616 if db_user:
1617 if db_user:
@@ -1626,36 +1627,33
1626
1627
1627 if _auth_token and token_match:
1628 if _auth_token and token_match:
1628 auth_token_access_valid = True
1629 auth_token_access_valid = True
1629 log.debug('AUTH TOKEN ****%s is VALID' % (_auth_token[-4:],))
1630 log.debug('AUTH TOKEN ****%s is VALID', _auth_token[-4:])
1630 else:
1631 else:
1631 auth_token_access_valid = False
1632 auth_token_access_valid = False
1632 if not _auth_token:
1633 if not _auth_token:
1633 log.debug("AUTH TOKEN *NOT* present in request")
1634 log.debug("AUTH TOKEN *NOT* present in request")
1634 else:
1635 else:
1635 log.warning(
1636 log.warning("AUTH TOKEN ****%s *NOT* valid", _auth_token[-4:])
1636 "AUTH TOKEN ****%s *NOT* valid" % _auth_token[-4:])
1637
1637
1638 log.debug('Checking if %s is authenticated @ %s', user.username, loc)
1638 log.debug('Checking if %s is authenticated @ %s' % (user.username, loc))
1639 reason = 'RHODECODE_AUTH' if user.is_authenticated \
1639 reason = 'RHODECODE_AUTH' if user.is_authenticated \
1640 else 'AUTH_TOKEN_AUTH'
1640 else 'AUTH_TOKEN_AUTH'
1641
1641
1642 if ip_access_valid and (
1642 if ip_access_valid and (
1643 user.is_authenticated or auth_token_access_valid):
1643 user.is_authenticated or auth_token_access_valid):
1644 log.info(
1644 log.info('user %s authenticating with:%s IS authenticated on func %s',
1645 'user %s authenticating with:%s IS authenticated on func %s'
1645 user, reason, loc)
1646 % (user, reason, loc))
1647
1646
1648 return func(*fargs, **fkwargs)
1647 return func(*fargs, **fkwargs)
1649 else:
1648 else:
1650 log.warning(
1649 log.warning(
1651 'user %s authenticating with:%s NOT authenticated on '
1650 'user %s authenticating with:%s NOT authenticated on '
1652 'func: %s: IP_ACCESS:%s AUTH_TOKEN_ACCESS:%s'
1651 'func: %s: IP_ACCESS:%s AUTH_TOKEN_ACCESS:%s',
1653 % (user, reason, loc, ip_access_valid,
1652 user, reason, loc, ip_access_valid, auth_token_access_valid)
1654 auth_token_access_valid))
1655 # we preserve the get PARAM
1653 # we preserve the get PARAM
1656 came_from = get_came_from(request)
1654 came_from = get_came_from(request)
1657
1655
1658 log.debug('redirecting to login page with %s' % (came_from,))
1656 log.debug('redirecting to login page with %s', came_from)
1659 raise HTTPFound(
1657 raise HTTPFound(
1660 h.route_path('login', _query={'came_from': came_from}))
1658 h.route_path('login', _query={'came_from': came_from}))
1661
1659
@@ -1678,7 +1676,7
1678 self.user = cls._rhodecode_user
1676 self.user = cls._rhodecode_user
1679 request = self._get_request()
1677 request = self._get_request()
1680 _ = request.translate
1678 _ = request.translate
1681 log.debug('Checking if user is not anonymous @%s' % cls)
1679 log.debug('Checking if user is not anonymous @%s', cls)
1682
1680
1683 anonymous = self.user.username == User.DEFAULT_USER
1681 anonymous = self.user.username == User.DEFAULT_USER
1684
1682
@@ -1939,7 +1937,7
1939 frame = inspect.currentframe()
1937 frame = inspect.currentframe()
1940 stack_trace = traceback.format_stack(frame)
1938 stack_trace = traceback.format_stack(frame)
1941 log.error('Checking bool value on a class instance of perm '
1939 log.error('Checking bool value on a class instance of perm '
1942 'function is not allowed: %s' % ''.join(stack_trace))
1940 'function is not allowed: %s', ''.join(stack_trace))
1943 # rather than throwing errors, here we always return False so if by
1941 # rather than throwing errors, here we always return False so if by
1944 # accident someone checks truth for just an instance it will always end
1942 # accident someone checks truth for just an instance it will always end
1945 # up in returning False
1943 # up in returning False
@@ -2182,9 +2180,8
2182 if user_group_name:
2180 if user_group_name:
2183 check_scope += ', user_group_name:%s' % (user_group_name,)
2181 check_scope += ', user_group_name:%s' % (user_group_name,)
2184
2182
2185 log.debug(
2183 log.debug('checking cls:%s %s %s @ %s',
2186 'checking cls:%s %s %s @ %s'
2184 cls_name, self.required_perms, check_scope, check_location)
2187 % (cls_name, self.required_perms, check_scope, check_location))
2188 if not user:
2185 if not user:
2189 log.debug('Empty User passed into arguments')
2186 log.debug('Empty User passed into arguments')
2190 return False
2187 return False
@@ -2305,7 +2302,7
2305 :param source_ip:
2302 :param source_ip:
2306 :param allowed_ips: list of allowed ips together with mask
2303 :param allowed_ips: list of allowed ips together with mask
2307 """
2304 """
2308 log.debug('checking if ip:%s is subnet of %s' % (source_ip, allowed_ips))
2305 log.debug('checking if ip:%s is subnet of %s', source_ip, allowed_ips)
2309 source_ip_address = ipaddress.ip_address(safe_unicode(source_ip))
2306 source_ip_address = ipaddress.ip_address(safe_unicode(source_ip))
2310 if isinstance(allowed_ips, (tuple, list, set)):
2307 if isinstance(allowed_ips, (tuple, list, set)):
2311 for ip in allowed_ips:
2308 for ip in allowed_ips:
@@ -2313,8 +2310,7
2313 try:
2310 try:
2314 network_address = ipaddress.ip_network(ip, strict=False)
2311 network_address = ipaddress.ip_network(ip, strict=False)
2315 if source_ip_address in network_address:
2312 if source_ip_address in network_address:
2316 log.debug('IP %s is network %s' %
2313 log.debug('IP %s is network %s', source_ip_address, network_address)
2317 (source_ip_address, network_address))
2318 return True
2314 return True
2319 # for any case we cannot determine the IP, don't crash just
2315 # for any case we cannot determine the IP, don't crash just
2320 # skip it and log as error, we want to say forbidden still when
2316 # skip it and log as error, we want to say forbidden still when
@@ -216,7 +216,7
216 try:
216 try:
217 return get_exception(safe_int(http_code))
217 return get_exception(safe_int(http_code))
218 except Exception:
218 except Exception:
219 log.exception('Failed to fetch response for code %s' % http_code)
219 log.exception('Failed to fetch response for code %s', http_code)
220 return HTTPForbidden
220 return HTTPForbidden
221
221
222 def get_rc_realm(self):
222 def get_rc_realm(self):
@@ -442,7 +442,7
442 return self._lexer_cache[filename]
442 return self._lexer_cache[filename]
443
443
444 def render_patch(self, patch):
444 def render_patch(self, patch):
445 log.debug('rendering diff for %r' % patch['filename'])
445 log.debug('rendering diff for %r', patch['filename'])
446
446
447 source_filename = patch['original_filename']
447 source_filename = patch['original_filename']
448 target_filename = patch['filename']
448 target_filename = patch['filename']
@@ -107,7 +107,7
107
107
108 checkfirst = not override
108 checkfirst = not override
109 Base.metadata.create_all(checkfirst=checkfirst)
109 Base.metadata.create_all(checkfirst=checkfirst)
110 log.info('Created tables for %s' % self.dbname)
110 log.info('Created tables for %s', self.dbname)
111
111
112 def set_db_version(self):
112 def set_db_version(self):
113 ver = DbMigrateVersion()
113 ver = DbMigrateVersion()
@@ -115,7 +115,7
115 ver.repository_id = 'rhodecode_db_migrations'
115 ver.repository_id = 'rhodecode_db_migrations'
116 ver.repository_path = 'versions'
116 ver.repository_path = 'versions'
117 self.sa.add(ver)
117 self.sa.add(ver)
118 log.info('db version set to: %s' % __dbversion__)
118 log.info('db version set to: %s', __dbversion__)
119
119
120 def run_pre_migration_tasks(self):
120 def run_pre_migration_tasks(self):
121 """
121 """
@@ -402,7 +402,7
402 ('auth_rhodecode_enabled', 'True', 'bool')]:
402 ('auth_rhodecode_enabled', 'True', 'bool')]:
403 if (skip_existing and
403 if (skip_existing and
404 SettingsModel().get_setting_by_name(k) is not None):
404 SettingsModel().get_setting_by_name(k) is not None):
405 log.debug('Skipping option %s' % k)
405 log.debug('Skipping option %s', k)
406 continue
406 continue
407 setting = RhodeCodeSetting(k, v, t)
407 setting = RhodeCodeSetting(k, v, t)
408 self.sa.add(setting)
408 self.sa.add(setting)
@@ -419,7 +419,7
419
419
420 if (skip_existing and
420 if (skip_existing and
421 SettingsModel().get_setting_by_name(k) is not None):
421 SettingsModel().get_setting_by_name(k) is not None):
422 log.debug('Skipping option %s' % k)
422 log.debug('Skipping option %s', k)
423 continue
423 continue