Show More
@@ -204,7 +204,7 b' def request_view(request):' | |||
|
204 | 204 | message='Request from IP:%s not allowed' % ( |
|
205 | 205 | request.rpc_ip_addr,)) |
|
206 | 206 | else: |
|
207 |
log.info('Access for IP:%s allowed' |
|
|
207 | log.info('Access for IP:%s allowed', request.rpc_ip_addr) | |
|
208 | 208 | |
|
209 | 209 | # register our auth-user |
|
210 | 210 | request.rpc_user = auth_u |
@@ -352,8 +352,7 b' def setup_request(request):' | |||
|
352 | 352 | request.rpc_params = json_body['args'] \ |
|
353 | 353 | if isinstance(json_body['args'], dict) else {} |
|
354 | 354 | |
|
355 | log.debug( | |
|
356 | 'method: %s, params: %s' % (request.rpc_method, request.rpc_params)) | |
|
355 | log.debug('method: %s, params: %s', request.rpc_method, request.rpc_params) | |
|
357 | 356 | except KeyError as e: |
|
358 | 357 | raise JSONRPCError('Incorrect JSON data. Missing %s' % e) |
|
359 | 358 |
@@ -405,8 +405,8 b' class GistView(BaseAppView):' | |||
|
405 | 405 | revision = self.request.GET.get('revision') |
|
406 | 406 | |
|
407 | 407 | if revision != last_rev.raw_id: |
|
408 | log.error('Last revision %s is different then submitted %s' | |
|
409 |
|
|
|
408 | log.error('Last revision %s is different then submitted %s', | |
|
409 | revision, last_rev) | |
|
410 | 410 | # our gist has newer version than we |
|
411 | 411 | success = False |
|
412 | 412 |
@@ -93,16 +93,16 b' def get_came_from(request):' | |||
|
93 | 93 | allowed_schemes = ['http', 'https'] |
|
94 | 94 | default_came_from = h.route_path('home') |
|
95 | 95 | if parsed.scheme and parsed.scheme not in allowed_schemes: |
|
96 |
log.error('Suspicious URL scheme detected %s for url %s' |
|
|
97 |
|
|
|
96 | log.error('Suspicious URL scheme detected %s for url %s', | |
|
97 | parsed.scheme, parsed) | |
|
98 | 98 | came_from = default_came_from |
|
99 | 99 | elif parsed.netloc and request.host != parsed.netloc: |
|
100 | 100 | log.error('Suspicious NETLOC detected %s for url %s server url ' |
|
101 |
'is: %s' |
|
|
101 | 'is: %s', parsed.netloc, parsed, request.host) | |
|
102 | 102 | came_from = default_came_from |
|
103 | 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 ' |
|
|
105 |
|
|
|
104 | log.error('Header injection detected `%s` for url %s server url ', | |
|
105 | parsed.path, parsed) | |
|
106 | 106 | came_from = default_came_from |
|
107 | 107 | |
|
108 | 108 | return came_from or default_came_from |
@@ -256,8 +256,8 b' class RepoCompareView(RepoAppView):' | |||
|
256 | 256 | # case we want a simple diff without incoming commits, |
|
257 | 257 | # previewing what will be merged. |
|
258 | 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' | |
|
260 |
|
|
|
259 | log.debug('Using ancestor %s as source_ref instead of %s', | |
|
260 | c.ancestor, source_ref) | |
|
261 | 261 | source_repo = target_repo |
|
262 | 262 | source_commit = target_repo.get_commit(commit_id=c.ancestor) |
|
263 | 263 |
@@ -98,8 +98,8 b' class StripView(RepoAppView):' | |||
|
98 | 98 | ScmModel().strip( |
|
99 | 99 | repo=self.db_repo, |
|
100 | 100 | commit_id=commit['rev'], branch=commit['branch']) |
|
101 |
log.info('Stripped commit %s from repo `%s` by %s' |
|
|
102 |
commit['rev'], self.db_repo_name, user) |
|
|
101 | log.info('Stripped commit %s from repo `%s` by %s', | |
|
102 | commit['rev'], self.db_repo_name, user) | |
|
103 | 103 | data[commit['rev']] = True |
|
104 | 104 | |
|
105 | 105 | audit_logger.store_web( |
@@ -108,6 +108,6 b' class StripView(RepoAppView):' | |||
|
108 | 108 | |
|
109 | 109 | except Exception as e: |
|
110 | 110 | data[commit['rev']] = False |
|
111 |
log.debug('Stripped commit %s from repo `%s` failed by %s, exeption %s' |
|
|
112 |
commit['rev'], self.db_repo_name, user, e.message) |
|
|
111 | log.debug('Stripped commit %s from repo `%s` failed by %s, exeption %s', | |
|
112 | commit['rev'], self.db_repo_name, user, e.message) | |
|
113 | 113 | return data |
@@ -241,16 +241,16 b' class RhodeCodeAuthPlugin(RhodeCodeExter' | |||
|
241 | 241 | log.debug('Empty username or password skipping...') |
|
242 | 242 | return None |
|
243 | 243 | |
|
244 |
log.debug("Crowd settings: \n%s" |
|
|
244 | log.debug("Crowd settings: \n%s", formatted_json(settings)) | |
|
245 | 245 | server = CrowdServer(**settings) |
|
246 | 246 | server.set_credentials(settings["app_name"], settings["app_password"]) |
|
247 | 247 | crowd_user = server.user_auth(username, password) |
|
248 |
log.debug("Crowd returned: \n%s" |
|
|
248 | log.debug("Crowd returned: \n%s", formatted_json(crowd_user)) | |
|
249 | 249 | if not crowd_user["status"]: |
|
250 | 250 | return None |
|
251 | 251 | |
|
252 | 252 | res = server.user_groups(crowd_user["name"]) |
|
253 |
log.debug("Crowd groups: \n%s" |
|
|
253 | log.debug("Crowd groups: \n%s", formatted_json(res)) | |
|
254 | 254 | crowd_user["groups"] = [x["name"] for x in res["groups"]] |
|
255 | 255 | |
|
256 | 256 | # old attrs fetched from RhodeCode database |
@@ -280,6 +280,6 b' class RhodeCodeAuthPlugin(RhodeCodeExter' | |||
|
280 | 280 | for group in settings["admin_groups"]: |
|
281 | 281 | if group in user_attrs["groups"]: |
|
282 | 282 | user_attrs["admin"] = True |
|
283 |
log.debug("Final crowd user object: \n%s" |
|
|
284 |
log.info('user `%s` authenticated correctly' |
|
|
283 | log.debug("Final crowd user object: \n%s", formatted_json(user_attrs)) | |
|
284 | log.info('user `%s` authenticated correctly', user_attrs['username']) | |
|
285 | 285 | return user_attrs |
@@ -125,24 +125,24 b' class RhodeCodeAuthPlugin(RhodeCodeExter' | |||
|
125 | 125 | username = None |
|
126 | 126 | environ = environ or {} |
|
127 | 127 | if not environ: |
|
128 |
log.debug('got empty environ: %s' |
|
|
128 | log.debug('got empty environ: %s', environ) | |
|
129 | 129 | |
|
130 | 130 | settings = settings or {} |
|
131 | 131 | if settings.get('header'): |
|
132 | 132 | header = settings.get('header') |
|
133 | 133 | username = environ.get(header) |
|
134 |
log.debug('extracted %s:%s' |
|
|
134 | log.debug('extracted %s:%s', header, username) | |
|
135 | 135 | |
|
136 | 136 | # fallback mode |
|
137 | 137 | if not username and settings.get('fallback_header'): |
|
138 | 138 | header = settings.get('fallback_header') |
|
139 | 139 | username = environ.get(header) |
|
140 |
log.debug('extracted %s:%s' |
|
|
140 | log.debug('extracted %s:%s', header, username) | |
|
141 | 141 | |
|
142 | 142 | if username and str2bool(settings.get('clean_username')): |
|
143 |
log.debug('Received username `%s` from headers' |
|
|
143 | log.debug('Received username `%s` from headers', username) | |
|
144 | 144 | username = self._clean_username(username) |
|
145 |
log.debug('New cleanup user is:%s' |
|
|
145 | log.debug('New cleanup user is:%s', username) | |
|
146 | 146 | return username |
|
147 | 147 | |
|
148 | 148 | def get_user(self, username=None, **kwargs): |
@@ -221,5 +221,5 b' class RhodeCodeAuthPlugin(RhodeCodeExter' | |||
|
221 | 221 | 'extern_type': extern_type, |
|
222 | 222 | } |
|
223 | 223 | |
|
224 |
log.info('user `%s` authenticated correctly' |
|
|
224 | log.info('user `%s` authenticated correctly', user_attrs['username']) | |
|
225 | 225 | return user_attrs |
@@ -134,10 +134,10 b' class RhodeCodeAuthPlugin(RhodeCodeExter' | |||
|
134 | 134 | try: |
|
135 | 135 | response = urllib2.urlopen(request) |
|
136 | 136 | except urllib2.HTTPError as e: |
|
137 |
log.debug("HTTPError when requesting Jasig CAS (status code: %d)" |
|
|
137 | log.debug("HTTPError when requesting Jasig CAS (status code: %d)", e.code) | |
|
138 | 138 | return None |
|
139 | 139 | except urllib2.URLError as e: |
|
140 |
log.debug("URLError when requesting Jasig CAS url: %s " |
|
|
140 | log.debug("URLError when requesting Jasig CAS url: %s ", url) | |
|
141 | 141 | return None |
|
142 | 142 | |
|
143 | 143 | # old attrs fetched from RhodeCode database |
@@ -163,5 +163,5 b' class RhodeCodeAuthPlugin(RhodeCodeExter' | |||
|
163 | 163 | 'extern_type': extern_type, |
|
164 | 164 | } |
|
165 | 165 | |
|
166 |
log.info('user `%s` authenticated correctly' |
|
|
166 | log.info('user `%s` authenticated correctly', user_attrs['username']) | |
|
167 | 167 | return user_attrs |
@@ -115,10 +115,10 b' class RhodeCodeAuthPlugin(RhodeCodeExter' | |||
|
115 | 115 | auth_result = _pam.authenticate(username, password, settings["service"]) |
|
116 | 116 | |
|
117 | 117 | if not auth_result: |
|
118 |
log.error("PAM was unable to authenticate user: %s" |
|
|
118 | log.error("PAM was unable to authenticate user: %s", username) | |
|
119 | 119 | return None |
|
120 | 120 | |
|
121 |
log.debug('Got PAM response %s' |
|
|
121 | log.debug('Got PAM response %s', auth_result) | |
|
122 | 122 | |
|
123 | 123 | # old attrs fetched from RhodeCode database |
|
124 | 124 | default_email = "%s@%s" % (username, socket.gethostname()) |
@@ -157,5 +157,5 b' class RhodeCodeAuthPlugin(RhodeCodeExter' | |||
|
157 | 157 | pass |
|
158 | 158 | |
|
159 | 159 | log.debug("pamuser: %s", user_attrs) |
|
160 |
log.info('user `%s` authenticated correctly' |
|
|
160 | log.info('user `%s` authenticated correctly', user_attrs['username']) | |
|
161 | 161 | return user_attrs |
@@ -87,12 +87,12 b' class RhodeCodeAuthPlugin(RhodeCodeAuthP' | |||
|
87 | 87 | |
|
88 | 88 | def auth(self, userobj, username, password, settings, **kwargs): |
|
89 | 89 | if not userobj: |
|
90 |
log.debug('userobj was:%s skipping' |
|
|
90 | log.debug('userobj was:%s skipping', userobj) | |
|
91 | 91 | return None |
|
92 | 92 | if userobj.extern_type != self.name: |
|
93 | 93 | log.warning( |
|
94 |
"userobj:%s extern_type mismatch got:`%s` expected:`%s`" |
|
|
95 |
|
|
|
94 | "userobj:%s extern_type mismatch got:`%s` expected:`%s`", | |
|
95 | userobj, userobj.extern_type, self.name) | |
|
96 | 96 | return None |
|
97 | 97 | |
|
98 | 98 | user_attrs = { |
@@ -109,7 +109,7 b' class RhodeCodeAuthPlugin(RhodeCodeAuthP' | |||
|
109 | 109 | "extern_type": userobj.extern_type, |
|
110 | 110 | } |
|
111 | 111 | |
|
112 |
log.debug("User attributes:%s" |
|
|
112 | log.debug("User attributes:%s", user_attrs) | |
|
113 | 113 | if userobj.active: |
|
114 | 114 | from rhodecode.lib import auth |
|
115 | 115 | crypto_backend = auth.crypto_backend() |
@@ -103,7 +103,7 b' class RhodeCodeAuthPlugin(RhodeCodeAuthP' | |||
|
103 | 103 | |
|
104 | 104 | def auth(self, userobj, username, password, settings, **kwargs): |
|
105 | 105 | if not userobj: |
|
106 |
log.debug('userobj was:%s skipping' |
|
|
106 | log.debug('userobj was:%s skipping', userobj) | |
|
107 | 107 | return None |
|
108 | 108 | |
|
109 | 109 | user_attrs = { |
@@ -133,7 +133,7 b' def _commits_as_dict(event, commit_ids, ' | |||
|
133 | 133 | missing_commits = set(commit_ids) - set(c['raw_id'] for c in commits) |
|
134 | 134 | if missing_commits: |
|
135 | 135 | log.error('Inconsistent repository state. ' |
|
136 |
'Missing commits: %s' |
|
|
136 | 'Missing commits: %s', ', '.join(missing_commits)) | |
|
137 | 137 | |
|
138 | 138 | return commits |
|
139 | 139 |
@@ -66,8 +66,8 b' def integrations_event_handler(event):' | |||
|
66 | 66 | exc_info = sys.exc_info() |
|
67 | 67 | store_exception(id(exc_info), exc_info) |
|
68 | 68 | log.exception( |
|
69 |
'failure occurred when sending event %s to integration %s' |
|
|
70 |
|
|
|
69 | 'failure occurred when sending event %s to integration %s', | |
|
70 | event, integration) | |
|
71 | 71 | |
|
72 | 72 | |
|
73 | 73 | def includeme(config): |
@@ -31,8 +31,7 b' class IntegrationTypeRegistry(collection' | |||
|
31 | 31 | key = IntegrationType.key |
|
32 | 32 | if key in self: |
|
33 | 33 | log.debug( |
|
34 |
'Overriding existing integration type %s (%s) with %s' |
|
|
35 |
|
|
|
34 | 'Overriding existing integration type %s (%s) with %s', | |
|
35 | self[key], key, IntegrationType) | |
|
36 | 36 | |
|
37 | 37 | self[key] = IntegrationType |
|
38 |
@@ -119,11 +119,11 b' class HipchatIntegrationType(Integration' | |||
|
119 | 119 | |
|
120 | 120 | def send_event(self, event): |
|
121 | 121 | if event.__class__ not in self.valid_events: |
|
122 |
log.debug('event not valid: %r' |
|
|
122 | log.debug('event not valid: %r', event) | |
|
123 | 123 | return |
|
124 | 124 | |
|
125 | 125 | if event.name not in self.settings['events']: |
|
126 |
log.debug('event ignored: %r' |
|
|
126 | log.debug('event ignored: %r', event) | |
|
127 | 127 | return |
|
128 | 128 | |
|
129 | 129 | data = event.as_dict() |
@@ -131,7 +131,7 b' class HipchatIntegrationType(Integration' | |||
|
131 | 131 | text = '<b>%s<b> caused a <b>%s</b> event' % ( |
|
132 | 132 | data['actor']['username'], event.name) |
|
133 | 133 | |
|
134 |
log.debug('handling hipchat event for %s' |
|
|
134 | log.debug('handling hipchat event for %s', event.name) | |
|
135 | 135 | |
|
136 | 136 | if isinstance(event, events.PullRequestCommentEvent): |
|
137 | 137 | text = self.format_pull_request_comment_event(event, data) |
@@ -144,7 +144,7 b' class HipchatIntegrationType(Integration' | |||
|
144 | 144 | elif isinstance(event, events.RepoCreateEvent): |
|
145 | 145 | text = self.format_repo_create_event(data) |
|
146 | 146 | else: |
|
147 |
log.error('unhandled event type: %r' |
|
|
147 | log.error('unhandled event type: %r', event) | |
|
148 | 148 | |
|
149 | 149 | run_task(post_text_to_hipchat, self.settings, text) |
|
150 | 150 | |
@@ -242,7 +242,7 b' class HipchatIntegrationType(Integration' | |||
|
242 | 242 | |
|
243 | 243 | @async_task(ignore_result=True, base=RequestContextTask) |
|
244 | 244 | def post_text_to_hipchat(settings, text): |
|
245 |
log.debug('sending %s to hipchat %s' |
|
|
245 | log.debug('sending %s to hipchat %s', text, settings['server_url']) | |
|
246 | 246 | json_message = { |
|
247 | 247 | "message": text, |
|
248 | 248 | "color": settings.get('color', 'yellow'), |
@@ -110,11 +110,11 b' class SlackIntegrationType(IntegrationTy' | |||
|
110 | 110 | |
|
111 | 111 | def send_event(self, event): |
|
112 | 112 | if event.__class__ not in self.valid_events: |
|
113 |
log.debug('event not valid: %r' |
|
|
113 | log.debug('event not valid: %r', event) | |
|
114 | 114 | return |
|
115 | 115 | |
|
116 | 116 | if event.name not in self.settings['events']: |
|
117 |
log.debug('event ignored: %r' |
|
|
117 | log.debug('event ignored: %r', event) | |
|
118 | 118 | return |
|
119 | 119 | |
|
120 | 120 | data = event.as_dict() |
@@ -127,7 +127,7 b' class SlackIntegrationType(IntegrationTy' | |||
|
127 | 127 | fields = None |
|
128 | 128 | overrides = None |
|
129 | 129 | |
|
130 |
log.debug('handling slack event for %s' |
|
|
130 | log.debug('handling slack event for %s', event.name) | |
|
131 | 131 | |
|
132 | 132 | if isinstance(event, events.PullRequestCommentEvent): |
|
133 | 133 | (title, text, fields, overrides) \ |
@@ -141,7 +141,7 b' class SlackIntegrationType(IntegrationTy' | |||
|
141 | 141 | elif isinstance(event, events.RepoCreateEvent): |
|
142 | 142 | title, text = self.format_repo_create_event(data) |
|
143 | 143 | else: |
|
144 |
log.error('unhandled event type: %r' |
|
|
144 | log.error('unhandled event type: %r', event) | |
|
145 | 145 | |
|
146 | 146 | run_task(post_text_to_slack, self.settings, title, text, fields, overrides) |
|
147 | 147 | |
@@ -314,8 +314,7 b' def html_to_slack_links(message):' | |||
|
314 | 314 | |
|
315 | 315 | @async_task(ignore_result=True, base=RequestContextTask) |
|
316 | 316 | def post_text_to_slack(settings, title, text, fields=None, overrides=None): |
|
317 |
log.debug('sending %s (%s) to slack %s' |
|
|
318 | title, text, settings['service'])) | |
|
317 | log.debug('sending %s (%s) to slack %s', title, text, settings['service']) | |
|
319 | 318 | |
|
320 | 319 | fields = fields or [] |
|
321 | 320 | overrides = overrides or {} |
@@ -171,11 +171,11 b' class WebhookIntegrationType(Integration' | |||
|
171 | 171 | 'handling event %s with Webhook integration %s', event.name, self) |
|
172 | 172 | |
|
173 | 173 | if event.__class__ not in self.valid_events: |
|
174 |
log.debug('event not valid: %r' |
|
|
174 | log.debug('event not valid: %r', event) | |
|
175 | 175 | return |
|
176 | 176 | |
|
177 | 177 | if event.name not in self.settings['events']: |
|
178 |
log.debug('event ignored: %r' |
|
|
178 | log.debug('event ignored: %r', event) | |
|
179 | 179 | return |
|
180 | 180 | |
|
181 | 181 | data = event.as_dict() |
@@ -979,7 +979,7 b' def allowed_auth_token_access(view_name,' | |||
|
979 | 979 | } |
|
980 | 980 | |
|
981 | 981 | log.debug( |
|
982 |
'Allowed views for AUTH TOKEN access: %s' |
|
|
982 | 'Allowed views for AUTH TOKEN access: %s', whitelist) | |
|
983 | 983 | auth_token_access_valid = False |
|
984 | 984 | |
|
985 | 985 | for entry in whitelist: |
@@ -998,8 +998,9 b' def allowed_auth_token_access(view_name,' | |||
|
998 | 998 | break |
|
999 | 999 | |
|
1000 | 1000 | if auth_token_access_valid: |
|
1001 | log.debug('view: `%s` matches entry in whitelist: %s' | |
|
1002 |
|
|
|
1001 | log.debug('view: `%s` matches entry in whitelist: %s', | |
|
1002 | view_name, whitelist) | |
|
1003 | ||
|
1003 | 1004 | else: |
|
1004 | 1005 | msg = ('view: `%s` does *NOT* match any entry in whitelist: %s' |
|
1005 | 1006 | % (view_name, whitelist)) |
@@ -1190,7 +1191,7 b' class AuthUser(object):' | |||
|
1190 | 1191 | |
|
1191 | 1192 | log.debug( |
|
1192 | 1193 | 'Computing PERMISSION tree for user %s scope `%s` ' |
|
1193 |
'with caching: %s[TTL: %ss]' |
|
|
1194 | 'with caching: %s[TTL: %ss]', user, scope, cache_on, cache_seconds or 0) | |
|
1194 | 1195 | |
|
1195 | 1196 | cache_namespace_uid = 'cache_user_auth.{}'.format(user_id) |
|
1196 | 1197 | region = rc_cache.get_or_create_region('cache_perms', cache_namespace_uid) |
@@ -1214,8 +1215,8 b' class AuthUser(object):' | |||
|
1214 | 1215 | for k in result: |
|
1215 | 1216 | result_repr.append((k, len(result[k]))) |
|
1216 | 1217 | total = time.time() - start |
|
1217 |
log.debug('PERMISSION tree for user %s computed in %.3fs: %s' |
|
|
1218 |
user, total, result_repr) |
|
|
1218 | log.debug('PERMISSION tree for user %s computed in %.3fs: %s', | |
|
1219 | user, total, result_repr) | |
|
1219 | 1220 | |
|
1220 | 1221 | return result |
|
1221 | 1222 | |
@@ -1352,12 +1353,12 b' class AuthUser(object):' | |||
|
1352 | 1353 | allowed_ips = AuthUser.get_allowed_ips( |
|
1353 | 1354 | user_id, cache=True, inherit_from_default=inherit_from_default) |
|
1354 | 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 |
ip_addr, user_id, allowed_ips) |
|
|
1356 | log.debug('IP:%s for user %s is in range of %s', | |
|
1357 | ip_addr, user_id, allowed_ips) | |
|
1357 | 1358 | return True |
|
1358 | 1359 | else: |
|
1359 | 1360 | log.info('Access for IP:%s forbidden for user %s, ' |
|
1360 |
'not in %s' |
|
|
1361 | 'not in %s', ip_addr, user_id, allowed_ips) | |
|
1361 | 1362 | return False |
|
1362 | 1363 | |
|
1363 | 1364 | def get_branch_permissions(self, repo_name, perms=None): |
@@ -1593,7 +1594,7 b' class LoginRequired(object):' | |||
|
1593 | 1594 | _ = request.translate |
|
1594 | 1595 | |
|
1595 | 1596 | loc = "%s:%s" % (cls.__class__.__name__, func.__name__) |
|
1596 |
log.debug('Starting login restriction checks for user: %s' |
|
|
1597 | log.debug('Starting login restriction checks for user: %s', user) | |
|
1597 | 1598 | # check if our IP is allowed |
|
1598 | 1599 | ip_access_valid = True |
|
1599 | 1600 | if not user.ip_allowed: |
@@ -1610,7 +1611,7 b' class LoginRequired(object):' | |||
|
1610 | 1611 | |
|
1611 | 1612 | # explicit controller is enabled or API is in our whitelist |
|
1612 | 1613 | if self.auth_token_access or auth_token_access_valid: |
|
1613 |
log.debug('Checking AUTH TOKEN access for %s' |
|
|
1614 | log.debug('Checking AUTH TOKEN access for %s', cls) | |
|
1614 | 1615 | db_user = user.get_instance() |
|
1615 | 1616 | |
|
1616 | 1617 | if db_user: |
@@ -1626,36 +1627,33 b' class LoginRequired(object):' | |||
|
1626 | 1627 | |
|
1627 | 1628 | if _auth_token and token_match: |
|
1628 | 1629 | auth_token_access_valid = True |
|
1629 |
log.debug('AUTH TOKEN ****%s is VALID' |
|
|
1630 | log.debug('AUTH TOKEN ****%s is VALID', _auth_token[-4:]) | |
|
1630 | 1631 | else: |
|
1631 | 1632 | auth_token_access_valid = False |
|
1632 | 1633 | if not _auth_token: |
|
1633 | 1634 | log.debug("AUTH TOKEN *NOT* present in request") |
|
1634 | 1635 | else: |
|
1635 | log.warning( | |
|
1636 | "AUTH TOKEN ****%s *NOT* valid" % _auth_token[-4:]) | |
|
1637 | ||
|
1638 | log.debug('Checking if %s is authenticated @ %s' % (user.username, loc)) | |
|
1636 | log.warning("AUTH TOKEN ****%s *NOT* valid", _auth_token[-4:]) | |
|
1637 | ||
|
1638 | log.debug('Checking if %s is authenticated @ %s', user.username, loc) | |
|
1639 | 1639 | reason = 'RHODECODE_AUTH' if user.is_authenticated \ |
|
1640 | 1640 | else 'AUTH_TOKEN_AUTH' |
|
1641 | 1641 | |
|
1642 | 1642 | if ip_access_valid and ( |
|
1643 | 1643 | user.is_authenticated or auth_token_access_valid): |
|
1644 | log.info( | |
|
1645 | 'user %s authenticating with:%s IS authenticated on func %s' | |
|
1646 | % (user, reason, loc)) | |
|
1644 | log.info('user %s authenticating with:%s IS authenticated on func %s', | |
|
1645 | user, reason, loc) | |
|
1647 | 1646 | |
|
1648 | 1647 | return func(*fargs, **fkwargs) |
|
1649 | 1648 | else: |
|
1650 | 1649 | log.warning( |
|
1651 | 1650 | 'user %s authenticating with:%s NOT authenticated on ' |
|
1652 | 'func: %s: IP_ACCESS:%s AUTH_TOKEN_ACCESS:%s' | |
|
1653 |
|
|
|
1654 | auth_token_access_valid)) | |
|
1651 | 'func: %s: IP_ACCESS:%s AUTH_TOKEN_ACCESS:%s', | |
|
1652 | user, reason, loc, ip_access_valid, auth_token_access_valid) | |
|
1655 | 1653 | # we preserve the get PARAM |
|
1656 | 1654 | came_from = get_came_from(request) |
|
1657 | 1655 | |
|
1658 |
log.debug('redirecting to login page with %s' |
|
|
1656 | log.debug('redirecting to login page with %s', came_from) | |
|
1659 | 1657 | raise HTTPFound( |
|
1660 | 1658 | h.route_path('login', _query={'came_from': came_from})) |
|
1661 | 1659 | |
@@ -1678,7 +1676,7 b' class NotAnonymous(object):' | |||
|
1678 | 1676 | self.user = cls._rhodecode_user |
|
1679 | 1677 | request = self._get_request() |
|
1680 | 1678 | _ = request.translate |
|
1681 |
log.debug('Checking if user is not anonymous @%s' |
|
|
1679 | log.debug('Checking if user is not anonymous @%s', cls) | |
|
1682 | 1680 | |
|
1683 | 1681 | anonymous = self.user.username == User.DEFAULT_USER |
|
1684 | 1682 | |
@@ -1939,7 +1937,7 b' class PermsFunction(object):' | |||
|
1939 | 1937 | frame = inspect.currentframe() |
|
1940 | 1938 | stack_trace = traceback.format_stack(frame) |
|
1941 | 1939 | log.error('Checking bool value on a class instance of perm ' |
|
1942 |
'function is not allowed: %s' |
|
|
1940 | 'function is not allowed: %s', ''.join(stack_trace)) | |
|
1943 | 1941 | # rather than throwing errors, here we always return False so if by |
|
1944 | 1942 | # accident someone checks truth for just an instance it will always end |
|
1945 | 1943 | # up in returning False |
@@ -2182,9 +2180,8 b' class _BaseApiPerm(object):' | |||
|
2182 | 2180 | if user_group_name: |
|
2183 | 2181 | check_scope += ', user_group_name:%s' % (user_group_name,) |
|
2184 | 2182 | |
|
2185 | log.debug( | |
|
2186 | 'checking cls:%s %s %s @ %s' | |
|
2187 | % (cls_name, self.required_perms, check_scope, check_location)) | |
|
2183 | log.debug('checking cls:%s %s %s @ %s', | |
|
2184 | cls_name, self.required_perms, check_scope, check_location) | |
|
2188 | 2185 | if not user: |
|
2189 | 2186 | log.debug('Empty User passed into arguments') |
|
2190 | 2187 | return False |
@@ -2305,7 +2302,7 b' def check_ip_access(source_ip, allowed_i' | |||
|
2305 | 2302 | :param source_ip: |
|
2306 | 2303 | :param allowed_ips: list of allowed ips together with mask |
|
2307 | 2304 | """ |
|
2308 |
log.debug('checking if ip:%s is subnet of %s' |
|
|
2305 | log.debug('checking if ip:%s is subnet of %s', source_ip, allowed_ips) | |
|
2309 | 2306 | source_ip_address = ipaddress.ip_address(safe_unicode(source_ip)) |
|
2310 | 2307 | if isinstance(allowed_ips, (tuple, list, set)): |
|
2311 | 2308 | for ip in allowed_ips: |
@@ -2313,8 +2310,7 b' def check_ip_access(source_ip, allowed_i' | |||
|
2313 | 2310 | try: |
|
2314 | 2311 | network_address = ipaddress.ip_network(ip, strict=False) |
|
2315 | 2312 | if source_ip_address in network_address: |
|
2316 |
log.debug('IP %s is network %s' |
|
|
2317 | (source_ip_address, network_address)) | |
|
2313 | log.debug('IP %s is network %s', source_ip_address, network_address) | |
|
2318 | 2314 | return True |
|
2319 | 2315 | # for any case we cannot determine the IP, don't crash just |
|
2320 | 2316 | # skip it and log as error, we want to say forbidden still when |
@@ -216,7 +216,7 b' class BasicAuth(AuthBasicAuthenticator):' | |||
|
216 | 216 | try: |
|
217 | 217 | return get_exception(safe_int(http_code)) |
|
218 | 218 | except Exception: |
|
219 |
log.exception('Failed to fetch response for code %s' |
|
|
219 | log.exception('Failed to fetch response for code %s', http_code) | |
|
220 | 220 | return HTTPForbidden |
|
221 | 221 | |
|
222 | 222 | def get_rc_realm(self): |
@@ -442,7 +442,7 b' class DiffSet(object):' | |||
|
442 | 442 | return self._lexer_cache[filename] |
|
443 | 443 | |
|
444 | 444 | def render_patch(self, patch): |
|
445 |
log.debug('rendering diff for %r' |
|
|
445 | log.debug('rendering diff for %r', patch['filename']) | |
|
446 | 446 | |
|
447 | 447 | source_filename = patch['original_filename'] |
|
448 | 448 | target_filename = patch['filename'] |
@@ -107,7 +107,7 b' class DbManage(object):' | |||
|
107 | 107 | |
|
108 | 108 | checkfirst = not override |
|
109 | 109 | Base.metadata.create_all(checkfirst=checkfirst) |
|
110 |
log.info('Created tables for %s' |
|
|
110 | log.info('Created tables for %s', self.dbname) | |
|
111 | 111 | |
|
112 | 112 | def set_db_version(self): |
|
113 | 113 | ver = DbMigrateVersion() |
@@ -115,7 +115,7 b' class DbManage(object):' | |||
|
115 | 115 | ver.repository_id = 'rhodecode_db_migrations' |
|
116 | 116 | ver.repository_path = 'versions' |
|
117 | 117 | self.sa.add(ver) |
|
118 |
log.info('db version set to: %s' |
|
|
118 | log.info('db version set to: %s', __dbversion__) | |
|
119 | 119 | |
|
120 | 120 | def run_pre_migration_tasks(self): |
|
121 | 121 | """ |
@@ -402,7 +402,7 b' class DbManage(object):' | |||
|
402 | 402 | ('auth_rhodecode_enabled', 'True', 'bool')]: |
|
403 | 403 | if (skip_existing and |
|
404 | 404 | SettingsModel().get_setting_by_name(k) is not None): |
|
405 |
log.debug('Skipping option %s' |
|
|
405 | log.debug('Skipping option %s', k) | |
|
406 | 406 | continue |
|
407 | 407 | setting = RhodeCodeSetting(k, v, t) |
|
408 | 408 | self.sa.add(setting) |
@@ -419,7 +419,7 b' class DbManage(object):' | |||
|
419 | 419 | |
|
420 | 420 | if (skip_existing and |
|
421 | 421 | SettingsModel().get_setting_by_name(k) is not None): |
|
422 |
log.debug('Skipping option %s' |
|
|
422 | log.debug('Skipping option %s', k) | |
|
423 | 423 | continue |
|
424 | 424 | setting = RhodeCodeSetting(k, v, t) |
|
425 | 425 | self.sa.add(setting) |
@@ -436,7 +436,7 b' class DbManage(object):' | |||
|
436 | 436 | .scalar() |
|
437 | 437 | |
|
438 | 438 | if default is None: |
|
439 |
log.debug('missing default permission for group %s adding' |
|
|
439 | log.debug('missing default permission for group %s adding', g) | |
|
440 | 440 | perm_obj = RepoGroupModel()._create_default_perms(g) |
|
441 | 441 | self.sa.add(perm_obj) |
|
442 | 442 | |
@@ -484,20 +484,20 b' class DbManage(object):' | |||
|
484 | 484 | # check proper dir |
|
485 | 485 | if not os.path.isdir(path): |
|
486 | 486 | path_ok = False |
|
487 |
log.error('Given path %s is not a valid directory' |
|
|
487 | log.error('Given path %s is not a valid directory', path) | |
|
488 | 488 | |
|
489 | 489 | elif not os.path.isabs(path): |
|
490 | 490 | path_ok = False |
|
491 |
log.error('Given path %s is not an absolute path' |
|
|
491 | log.error('Given path %s is not an absolute path', path) | |
|
492 | 492 | |
|
493 | 493 | # check if path is at least readable. |
|
494 | 494 | if not os.access(path, os.R_OK): |
|
495 | 495 | path_ok = False |
|
496 |
log.error('Given path %s is not readable' |
|
|
496 | log.error('Given path %s is not readable', path) | |
|
497 | 497 | |
|
498 | 498 | # check write access, warn user about non writeable paths |
|
499 | 499 | elif not os.access(path, os.W_OK) and path_ok: |
|
500 |
log.warning('No write permission to given path %s' |
|
|
500 | log.warning('No write permission to given path %s', path) | |
|
501 | 501 | |
|
502 | 502 | q = ('Given path %s is not writeable, do you want to ' |
|
503 | 503 | 'continue with read only mode ? [y/n]' % (path,)) |
@@ -573,7 +573,7 b' class DbManage(object):' | |||
|
573 | 573 | |
|
574 | 574 | def create_user(self, username, password, email='', admin=False, |
|
575 | 575 | strict_creation_check=True, api_key=None): |
|
576 |
log.info('creating user `%s`' |
|
|
576 | log.info('creating user `%s`', username) | |
|
577 | 577 | user = UserModel().create_or_update( |
|
578 | 578 | username, password, email, firstname=u'RhodeCode', lastname=u'Admin', |
|
579 | 579 | active=True, admin=admin, extern_type="rhodecode", |
@@ -25,13 +25,13 b' def usage():' | |||
|
25 | 25 | |
|
26 | 26 | def delete_file(filepath): |
|
27 | 27 | """Deletes a file and prints a message.""" |
|
28 |
log.info('Deleting file: %s' |
|
|
28 | log.info('Deleting file: %s', filepath) | |
|
29 | 29 | os.remove(filepath) |
|
30 | 30 | |
|
31 | 31 | |
|
32 | 32 | def move_file(src, tgt): |
|
33 | 33 | """Moves a file and prints a message.""" |
|
34 |
log.info('Moving file %s to %s' |
|
|
34 | log.info('Moving file %s to %s', src, tgt) | |
|
35 | 35 | if os.path.exists(tgt): |
|
36 | 36 | raise Exception( |
|
37 | 37 | 'Cannot move file %s because target %s already exists' % \ |
@@ -41,13 +41,13 b' def move_file(src, tgt):' | |||
|
41 | 41 | |
|
42 | 42 | def delete_directory(dirpath): |
|
43 | 43 | """Delete a directory and print a message.""" |
|
44 |
log.info('Deleting directory: %s' |
|
|
44 | log.info('Deleting directory: %s', dirpath) | |
|
45 | 45 | os.rmdir(dirpath) |
|
46 | 46 | |
|
47 | 47 | |
|
48 | 48 | def migrate_repository(repos): |
|
49 | 49 | """Does the actual migration to the new repository format.""" |
|
50 |
log.info('Migrating repository at: %s to new format' |
|
|
50 | log.info('Migrating repository at: %s to new format', repos) | |
|
51 | 51 | versions = '%s/versions' % repos |
|
52 | 52 | dirs = os.listdir(versions) |
|
53 | 53 | # Only use int's in list. |
@@ -55,7 +55,7 b' def migrate_repository(repos):' | |||
|
55 | 55 | numdirs.sort() # Sort list. |
|
56 | 56 | for dirname in numdirs: |
|
57 | 57 | origdir = '%s/%s' % (versions, dirname) |
|
58 |
log.info('Working on directory: %s' |
|
|
58 | log.info('Working on directory: %s', origdir) | |
|
59 | 59 | files = os.listdir(origdir) |
|
60 | 60 | files.sort() |
|
61 | 61 | for filename in files: |
@@ -35,7 +35,7 b' class Pathed(KeyedInstance):' | |||
|
35 | 35 | """Try to initialize this object's parent, if it has one""" |
|
36 | 36 | parent_path = self.__class__._parent_path(path) |
|
37 | 37 | self.parent = self.__class__.parent(parent_path) |
|
38 |
log.debug("Getting parent %r:%r" |
|
|
38 | log.debug("Getting parent %r:%r", self.__class__.parent, parent_path) | |
|
39 | 39 | self.parent._init_child(path, self) |
|
40 | 40 | |
|
41 | 41 | def _init_child(self, child, path): |
@@ -73,14 +73,14 b' class Repository(pathed.Pathed):' | |||
|
73 | 73 | _versions = 'versions' |
|
74 | 74 | |
|
75 | 75 | def __init__(self, path): |
|
76 |
log.debug('Loading repository %s...' |
|
|
76 | log.debug('Loading repository %s...', path) | |
|
77 | 77 | self.verify(path) |
|
78 | 78 | super(Repository, self).__init__(path) |
|
79 | 79 | self.config = cfgparse.Config(os.path.join(self.path, self._config)) |
|
80 | 80 | self.versions = version.Collection(os.path.join(self.path, |
|
81 | 81 | self._versions)) |
|
82 |
log.debug('Repository %s loaded successfully' |
|
|
83 |
log.debug('Config: %r' |
|
|
82 | log.debug('Repository %s loaded successfully', path) | |
|
83 | log.debug('Config: %r', self.config.to_dict()) | |
|
84 | 84 | |
|
85 | 85 | @classmethod |
|
86 | 86 | def verify(cls, path): |
@@ -24,10 +24,10 b' class BaseScript(pathed.Pathed):' | |||
|
24 | 24 | """ # TODO: sphinxfy this and implement it correctly |
|
25 | 25 | |
|
26 | 26 | def __init__(self, path): |
|
27 |
log.debug('Loading script %s...' |
|
|
27 | log.debug('Loading script %s...', path) | |
|
28 | 28 | self.verify(path) |
|
29 | 29 | super(BaseScript, self).__init__(path) |
|
30 |
log.debug('Script %s loaded successfully' |
|
|
30 | log.debug('Script %s loaded successfully', path) | |
|
31 | 31 | |
|
32 | 32 | @classmethod |
|
33 | 33 | def verify(cls, path): |
@@ -311,7 +311,7 b' class User(Base, BaseModel):' | |||
|
311 | 311 | self.last_login = datetime.datetime.now() |
|
312 | 312 | Session.add(self) |
|
313 | 313 | Session.commit() |
|
314 |
log.debug('updated user %s lastlogin' |
|
|
314 | log.debug('updated user %s lastlogin', self.username) | |
|
315 | 315 | |
|
316 | 316 | @classmethod |
|
317 | 317 | def create(cls, form_data): |
@@ -656,7 +656,7 b' class Repository(Base, BaseModel):' | |||
|
656 | 656 | |
|
657 | 657 | try: |
|
658 | 658 | alias = get_scm(repo_full_path)[0] |
|
659 |
log.debug('Creating instance of %s repository' |
|
|
659 | log.debug('Creating instance of %s repository', alias) | |
|
660 | 660 | backend = get_backend(alias) |
|
661 | 661 | except VCSError: |
|
662 | 662 | log.error(traceback.format_exc()) |
@@ -731,7 +731,7 b' class Group(Base, BaseModel):' | |||
|
731 | 731 | break |
|
732 | 732 | if cnt == parents_recursion_limit: |
|
733 | 733 | # this will prevent accidental infinit loops |
|
734 |
log.error('group nested more than %s' |
|
|
734 | log.error('group nested more than %s', | |
|
735 | 735 | parents_recursion_limit) |
|
736 | 736 | break |
|
737 | 737 | |
@@ -1006,7 +1006,7 b' class CacheInvalidation(Base, BaseModel)' | |||
|
1006 | 1006 | :param key: |
|
1007 | 1007 | """ |
|
1008 | 1008 | |
|
1009 |
log.debug('marking %s for invalidation' |
|
|
1009 | log.debug('marking %s for invalidation', key) | |
|
1010 | 1010 | inv_obj = Session.query(cls)\ |
|
1011 | 1011 | .filter(cls.cache_key == key).scalar() |
|
1012 | 1012 | if inv_obj: |
@@ -379,7 +379,7 b' class User(Base, BaseModel):' | |||
|
379 | 379 | """Update user lastlogin""" |
|
380 | 380 | self.last_login = datetime.datetime.now() |
|
381 | 381 | Session.add(self) |
|
382 |
log.debug('updated user %s lastlogin' |
|
|
382 | log.debug('updated user %s lastlogin', self.username) | |
|
383 | 383 | |
|
384 | 384 | def __json__(self): |
|
385 | 385 | return dict( |
@@ -676,7 +676,7 b' class Repository(Base, BaseModel):' | |||
|
676 | 676 | repo_full_path = self.repo_full_path |
|
677 | 677 | try: |
|
678 | 678 | alias = get_scm(repo_full_path)[0] |
|
679 |
log.debug('Creating instance of %s repository' |
|
|
679 | log.debug('Creating instance of %s repository', alias) | |
|
680 | 680 | backend = get_backend(alias) |
|
681 | 681 | except VCSError: |
|
682 | 682 | log.error(traceback.format_exc()) |
@@ -760,8 +760,7 b' class RepoGroup(Base, BaseModel):' | |||
|
760 | 760 | break |
|
761 | 761 | if cnt == parents_recursion_limit: |
|
762 | 762 | # this will prevent accidental infinit loops |
|
763 |
log.error('group nested more than %s' |
|
|
764 | parents_recursion_limit) | |
|
763 | log.error('group nested more than %s', parents_recursion_limit) | |
|
765 | 764 | break |
|
766 | 765 | |
|
767 | 766 | groups.insert(0, gr) |
@@ -1095,8 +1094,7 b' class CacheInvalidation(Base, BaseModel)' | |||
|
1095 | 1094 | |
|
1096 | 1095 | key, _prefix, _org_key = cls._get_key(key) |
|
1097 | 1096 | inv_objs = Session.query(cls).filter(cls.cache_args == _org_key).all() |
|
1098 |
log.debug('marking %s key[s] %s for invalidation' |
|
|
1099 | _org_key)) | |
|
1097 | log.debug('marking %s key[s] %s for invalidation', len(inv_objs), _org_key) | |
|
1100 | 1098 | try: |
|
1101 | 1099 | for inv_obj in inv_objs: |
|
1102 | 1100 | if inv_obj: |
@@ -614,15 +614,13 b' class Repository(Base, BaseModel):' | |||
|
614 | 614 | if (cs_cache != self.changeset_cache or not self.changeset_cache): |
|
615 | 615 | _default = datetime.datetime.fromtimestamp(0) |
|
616 | 616 | last_change = cs_cache.get('date') or _default |
|
617 | log.debug('updated repo %s with new cs cache %s' | |
|
618 | % (self.repo_name, cs_cache)) | |
|
617 | log.debug('updated repo %s with new cs cache %s', self.repo_name, cs_cache) | |
|
619 | 618 | self.updated_on = last_change |
|
620 | 619 | self.changeset_cache = cs_cache |
|
621 | 620 | Session().add(self) |
|
622 | 621 | Session().commit() |
|
623 | 622 | else: |
|
624 | log.debug('Skipping repo:%s already with latest changes' | |
|
625 | % self.repo_name) | |
|
623 | log.debug('Skipping repo:%s already with latest changes', self.repo_name) | |
|
626 | 624 | |
|
627 | 625 | class RepoGroup(Base, BaseModel): |
|
628 | 626 | __tablename__ = 'groups' |
@@ -2415,8 +2415,8 b' class RepoGroup(Base, BaseModel):' | |||
|
2415 | 2415 | break |
|
2416 | 2416 | if cnt == parents_recursion_limit: |
|
2417 | 2417 | # this will prevent accidental infinit loops |
|
2418 |
log.error |
|
|
2419 |
|
|
|
2418 | log.error('more than %s parents found for group %s, stopping ' | |
|
2419 | 'recursive parent fetching', parents_recursion_limit, self) | |
|
2420 | 2420 | break |
|
2421 | 2421 | |
|
2422 | 2422 | groups.insert(0, gr) |
@@ -2481,8 +2481,8 b' class RepoGroup(Base, BaseModel):' | |||
|
2481 | 2481 | break |
|
2482 | 2482 | if cnt == parents_recursion_limit: |
|
2483 | 2483 | # this will prevent accidental infinit loops |
|
2484 |
log.error |
|
|
2485 |
|
|
|
2484 | log.error('more than %s parents found for group %s, stopping ' | |
|
2485 | 'recursive parent fetching', parents_recursion_limit, self) | |
|
2486 | 2486 | break |
|
2487 | 2487 | |
|
2488 | 2488 | groups.insert(0, gr) |
@@ -2108,8 +2108,8 b' class RepoGroup(Base, BaseModel):' | |||
|
2108 | 2108 | break |
|
2109 | 2109 | if cnt == parents_recursion_limit: |
|
2110 | 2110 | # this will prevent accidental infinit loops |
|
2111 |
log.error |
|
|
2112 |
|
|
|
2111 | log.error('more than %s parents found for group %s, stopping ' | |
|
2112 | 'recursive parent fetching', parents_recursion_limit, self) | |
|
2113 | 2113 | break |
|
2114 | 2114 | |
|
2115 | 2115 | groups.insert(0, gr) |
@@ -2100,8 +2100,8 b' class RepoGroup(Base, BaseModel):' | |||
|
2100 | 2100 | break |
|
2101 | 2101 | if cnt == parents_recursion_limit: |
|
2102 | 2102 | # this will prevent accidental infinit loops |
|
2103 |
log.error |
|
|
2104 |
|
|
|
2103 | log.error('more than %s parents found for group %s, stopping ' | |
|
2104 | 'recursive parent fetching', parents_recursion_limit, self) | |
|
2105 | 2105 | break |
|
2106 | 2106 | |
|
2107 | 2107 | groups.insert(0, gr) |
@@ -2100,8 +2100,8 b' class RepoGroup(Base, BaseModel):' | |||
|
2100 | 2100 | break |
|
2101 | 2101 | if cnt == parents_recursion_limit: |
|
2102 | 2102 | # this will prevent accidental infinit loops |
|
2103 |
log.error |
|
|
2104 |
|
|
|
2103 | log.error('more than %s parents found for group %s, stopping ' | |
|
2104 | 'recursive parent fetching', parents_recursion_limit, self) | |
|
2105 | 2105 | break |
|
2106 | 2106 | |
|
2107 | 2107 | groups.insert(0, gr) |
@@ -2104,8 +2104,8 b' class RepoGroup(Base, BaseModel):' | |||
|
2104 | 2104 | break |
|
2105 | 2105 | if cnt == parents_recursion_limit: |
|
2106 | 2106 | # this will prevent accidental infinit loops |
|
2107 |
log.error |
|
|
2108 |
|
|
|
2107 | log.error('more than %s parents found for group %s, stopping ' | |
|
2108 | 'recursive parent fetching', parents_recursion_limit, self) | |
|
2109 | 2109 | break |
|
2110 | 2110 | |
|
2111 | 2111 | groups.insert(0, gr) |
@@ -2104,8 +2104,8 b' class RepoGroup(Base, BaseModel):' | |||
|
2104 | 2104 | break |
|
2105 | 2105 | if cnt == parents_recursion_limit: |
|
2106 | 2106 | # this will prevent accidental infinit loops |
|
2107 |
log.error |
|
|
2108 |
|
|
|
2107 | log.error('more than %s parents found for group %s, stopping ' | |
|
2108 | 'recursive parent fetching', parents_recursion_limit, self) | |
|
2109 | 2109 | break |
|
2110 | 2110 | |
|
2111 | 2111 | groups.insert(0, gr) |
@@ -2154,8 +2154,8 b' class RepoGroup(Base, BaseModel):' | |||
|
2154 | 2154 | break |
|
2155 | 2155 | if cnt == parents_recursion_limit: |
|
2156 | 2156 | # this will prevent accidental infinit loops |
|
2157 |
log.error |
|
|
2158 |
|
|
|
2157 | log.error('more than %s parents found for group %s, stopping ' | |
|
2158 | 'recursive parent fetching', parents_recursion_limit, self) | |
|
2159 | 2159 | break |
|
2160 | 2160 | |
|
2161 | 2161 | groups.insert(0, gr) |
@@ -2155,8 +2155,8 b' class RepoGroup(Base, BaseModel):' | |||
|
2155 | 2155 | break |
|
2156 | 2156 | if cnt == parents_recursion_limit: |
|
2157 | 2157 | # this will prevent accidental infinit loops |
|
2158 |
log.error |
|
|
2159 |
|
|
|
2158 | log.error('more than %s parents found for group %s, stopping ' | |
|
2159 | 'recursive parent fetching', parents_recursion_limit, self) | |
|
2160 | 2160 | break |
|
2161 | 2161 | |
|
2162 | 2162 | groups.insert(0, gr) |
@@ -2352,8 +2352,8 b' class RepoGroup(Base, BaseModel):' | |||
|
2352 | 2352 | break |
|
2353 | 2353 | if cnt == parents_recursion_limit: |
|
2354 | 2354 | # this will prevent accidental infinit loops |
|
2355 |
log.error |
|
|
2356 |
|
|
|
2355 | log.error('more than %s parents found for group %s, stopping ' | |
|
2356 | 'recursive parent fetching', parents_recursion_limit, self) | |
|
2357 | 2357 | break |
|
2358 | 2358 | |
|
2359 | 2359 | groups.insert(0, gr) |
@@ -74,7 +74,7 b' class User(Base):' | |||
|
74 | 74 | self.last_login = datetime.datetime.now() |
|
75 | 75 | session.add(self) |
|
76 | 76 | session.commit() |
|
77 |
log.debug('updated user %s lastlogin' |
|
|
77 | log.debug('updated user %s lastlogin', self.username) | |
|
78 | 78 | except (DatabaseError,): |
|
79 | 79 | session.rollback() |
|
80 | 80 |
@@ -102,7 +102,7 b' def fixups(models, _SESSION):' | |||
|
102 | 102 | perms = models.UserToPerm.query().filter(models.UserToPerm.user == user).all() |
|
103 | 103 | defined_perms_groups = map( |
|
104 | 104 | _get_group, (x.permission.permission_name for x in perms)) |
|
105 |
log.debug('GOT ALREADY DEFINED:%s' |
|
|
105 | log.debug('GOT ALREADY DEFINED:%s', perms) | |
|
106 | 106 | DEFAULT_PERMS = models.Permission.DEFAULT_USER_PERMISSIONS |
|
107 | 107 | |
|
108 | 108 | # for every default permission that needs to be created, we check if |
@@ -110,8 +110,7 b' def fixups(models, _SESSION):' | |||
|
110 | 110 | for perm_name in DEFAULT_PERMS: |
|
111 | 111 | gr = _get_group(perm_name) |
|
112 | 112 | if gr not in defined_perms_groups: |
|
113 | log.debug('GR:%s not found, creating permission %s' | |
|
114 | % (gr, perm_name)) | |
|
113 | log.debug('GR:%s not found, creating permission %s', gr, perm_name) | |
|
115 | 114 | new_perm = _make_perm(perm_name) |
|
116 | 115 | _SESSION().add(new_perm) |
|
117 | 116 | _SESSION().commit() |
@@ -127,7 +126,7 b' def fixups(models, _SESSION):' | |||
|
127 | 126 | ('default_repo_type', 'hg')]: |
|
128 | 127 | |
|
129 | 128 | if skip_existing and get_by_name(models.RhodeCodeSetting, k) is not None: |
|
130 |
log.debug('Skipping option %s' |
|
|
129 | log.debug('Skipping option %s', k) | |
|
131 | 130 | continue |
|
132 | 131 | setting = models.RhodeCodeSetting(k, v) |
|
133 | 132 | _SESSION().add(setting) |
@@ -99,7 +99,7 b' def fixups(models, _SESSION):' | |||
|
99 | 99 | perms = models.UserToPerm.query().filter(models.UserToPerm.user == user).all() |
|
100 | 100 | defined_perms_groups = map(_get_group, |
|
101 | 101 | (x.permission.permission_name for x in perms)) |
|
102 |
log.debug('GOT ALREADY DEFINED:%s' |
|
|
102 | log.debug('GOT ALREADY DEFINED:%s', perms) | |
|
103 | 103 | DEFAULT_PERMS = models.Permission.DEFAULT_USER_PERMISSIONS |
|
104 | 104 | |
|
105 | 105 | # for every default permission that needs to be created, we check if |
@@ -107,8 +107,7 b' def fixups(models, _SESSION):' | |||
|
107 | 107 | for perm_name in DEFAULT_PERMS: |
|
108 | 108 | gr = _get_group(perm_name) |
|
109 | 109 | if gr not in defined_perms_groups: |
|
110 | log.debug('GR:%s not found, creating permission %s' | |
|
111 | % (gr, perm_name)) | |
|
110 | log.debug('GR:%s not found, creating permission %s', gr, perm_name) | |
|
112 | 111 | new_perm = _make_perm(perm_name) |
|
113 | 112 | _SESSION().add(new_perm) |
|
114 | 113 | _SESSION().commit() |
@@ -446,7 +446,7 b' class DiffProcessor(object):' | |||
|
446 | 446 | |
|
447 | 447 | for chunk in self._diff.chunks(): |
|
448 | 448 | head = chunk.header |
|
449 |
log.debug('parsing diff %r' |
|
|
449 | log.debug('parsing diff %r', head) | |
|
450 | 450 | |
|
451 | 451 | raw_diff = chunk.raw |
|
452 | 452 | limited_diff = False |
@@ -1712,14 +1712,14 b' def process_patterns(text_string, repo_n' | |||
|
1712 | 1712 | newtext = text_string |
|
1713 | 1713 | |
|
1714 | 1714 | for uid, entry in active_entries.items(): |
|
1715 |
log.debug('found issue tracker entry with uid %s' |
|
|
1715 | log.debug('found issue tracker entry with uid %s', uid) | |
|
1716 | 1716 | |
|
1717 | 1717 | if not (entry['pat'] and entry['url']): |
|
1718 | 1718 | log.debug('skipping due to missing data') |
|
1719 | 1719 | continue |
|
1720 | 1720 | |
|
1721 | log.debug('issue tracker entry: uid: `%s` PAT:%s URL:%s PREFIX:%s' | |
|
1722 |
|
|
|
1721 | log.debug('issue tracker entry: uid: `%s` PAT:%s URL:%s PREFIX:%s', | |
|
1722 | uid, entry['pat'], entry['url'], entry['pref']) | |
|
1723 | 1723 | |
|
1724 | 1724 | try: |
|
1725 | 1725 | pattern = re.compile(r'%s' % entry['pat']) |
@@ -1741,7 +1741,7 b' def process_patterns(text_string, repo_n' | |||
|
1741 | 1741 | link_format=link_format) |
|
1742 | 1742 | |
|
1743 | 1743 | newtext = pattern.sub(url_func, newtext) |
|
1744 |
log.debug('processed prefix:uid `%s`' |
|
|
1744 | log.debug('processed prefix:uid `%s`', uid) | |
|
1745 | 1745 | |
|
1746 | 1746 | return newtext, issues_data |
|
1747 | 1747 |
@@ -122,7 +122,7 b' class Search(BaseSearch):' | |||
|
122 | 122 | search_user, repo_name) |
|
123 | 123 | try: |
|
124 | 124 | query = qp.parse(safe_unicode(query)) |
|
125 |
log.debug('query: %s (%s)' |
|
|
125 | log.debug('query: %s (%s)', query, repr(query)) | |
|
126 | 126 | |
|
127 | 127 | reverse, sortedby = False, None |
|
128 | 128 | if search_type == 'message': |
@@ -217,8 +217,8 b' class Search(BaseSearch):' | |||
|
217 | 217 | 'path': self.file_schema |
|
218 | 218 | }.get(cur_type, self.file_schema) |
|
219 | 219 | |
|
220 |
log.debug('IDX: %s' |
|
|
221 |
log.debug('SCHEMA: %s' |
|
|
220 | log.debug('IDX: %s', index_name) | |
|
221 | log.debug('SCHEMA: %s', schema_defn) | |
|
222 | 222 | return search_type, index_name, schema_defn |
|
223 | 223 | |
|
224 | 224 | def _init_searcher(self, index_name): |
@@ -67,7 +67,7 b' class LRUDictDebug(LRUDict):' | |||
|
67 | 67 | fmt = '\n' |
|
68 | 68 | for cnt, elem in enumerate(self.keys()): |
|
69 | 69 | fmt += '%s - %s\n' % (cnt+1, safe_str(elem)) |
|
70 |
log.debug('current LRU keys (%s):%s' |
|
|
70 | log.debug('current LRU keys (%s):%s', elems_cnt, fmt) | |
|
71 | 71 | |
|
72 | 72 | def __getitem__(self, key): |
|
73 | 73 | self._report_keys() |
@@ -44,10 +44,11 b' class RequestWrapperTween(object):' | |||
|
44 | 44 | finally: |
|
45 | 45 | end = time.time() |
|
46 | 46 | total = end - start |
|
47 | log.info('IP: %s Request to %s time: %.3fs [%s]' % ( | |
|
47 | log.info( | |
|
48 | 'IP: %s Request to %s time: %.3fs [%s]', | |
|
48 | 49 | get_ip_addr(request.environ), |
|
49 | 50 | safe_str(get_access_path(request.environ)), total, |
|
50 |
get_user_agent(request. environ) |
|
|
51 | get_user_agent(request. environ) | |
|
51 | 52 | ) |
|
52 | 53 | |
|
53 | 54 | return response |
@@ -237,7 +237,7 b' class InvalidationContext(object):' | |||
|
237 | 237 | result = heavy_compute(*args) |
|
238 | 238 | |
|
239 | 239 | compute_time = inv_context_manager.compute_time |
|
240 |
log.debug('result computed in %.3fs' |
|
|
240 | log.debug('result computed in %.3fs', compute_time) | |
|
241 | 241 | |
|
242 | 242 | # To send global invalidation signal, simply run |
|
243 | 243 | CacheKey.set_invalidate(invalidation_namespace) |
@@ -111,7 +111,7 b' class SmtpMailer(object):' | |||
|
111 | 111 | smtp_serv.login(self.user, self.passwd) |
|
112 | 112 | |
|
113 | 113 | smtp_serv.sendmail(msg.sender, msg.send_to, raw_msg.as_string()) |
|
114 |
log.info('email sent to: %s' |
|
|
114 | log.info('email sent to: %s', recipients) | |
|
115 | 115 | |
|
116 | 116 | try: |
|
117 | 117 | smtp_serv.quit() |
@@ -49,13 +49,13 b' def user_log_filter(user_log, search_ter' | |||
|
49 | 49 | :param user_log: |
|
50 | 50 | :param search_term: |
|
51 | 51 | """ |
|
52 |
log.debug('Initial search term: %r' |
|
|
52 | log.debug('Initial search term: %r', search_term) | |
|
53 | 53 | qry = None |
|
54 | 54 | if search_term: |
|
55 | 55 | qp = QueryParser('repository', schema=JOURNAL_SCHEMA) |
|
56 | 56 | qp.add_plugin(DateParserPlugin()) |
|
57 | 57 | qry = qp.parse(safe_unicode(search_term)) |
|
58 |
log.debug('Filtering using parsed query %r' |
|
|
58 | log.debug('Filtering using parsed query %r', qry) | |
|
59 | 59 | |
|
60 | 60 | def wildcard_handler(col, wc_term): |
|
61 | 61 | if wc_term.startswith('*') and not wc_term.endswith('*'): |
@@ -80,7 +80,7 b' def user_log_filter(user_log, search_ter' | |||
|
80 | 80 | field = getattr(UserLog, 'username') |
|
81 | 81 | else: |
|
82 | 82 | field = getattr(UserLog, field) |
|
83 |
log.debug('filter field: %s val=>%s' |
|
|
83 | log.debug('filter field: %s val=>%s', field, val) | |
|
84 | 84 | |
|
85 | 85 | # sql filtering |
|
86 | 86 | if isinstance(term, query.Wildcard): |
@@ -291,8 +291,7 b' def is_valid_repo_group(repo_group_name,' | |||
|
291 | 291 | |
|
292 | 292 | # check if it's not a repo |
|
293 | 293 | if is_valid_repo(repo_group_name, base_path): |
|
294 | log.debug('Repo called %s exist, it is not a valid ' | |
|
295 | 'repo group' % repo_group_name) | |
|
294 | log.debug('Repo called %s exist, it is not a valid repo group', repo_group_name) | |
|
296 | 295 | return False |
|
297 | 296 | |
|
298 | 297 | try: |
@@ -300,8 +299,7 b' def is_valid_repo_group(repo_group_name,' | |||
|
300 | 299 | # since we might match branches/hooks/info/objects or possible |
|
301 | 300 | # other things inside bare git repo |
|
302 | 301 | scm_ = get_scm(os.path.dirname(full_path)) |
|
303 | log.debug('path: %s is a vcs object:%s, not valid ' | |
|
304 | 'repo group' % (full_path, scm_)) | |
|
302 | log.debug('path: %s is a vcs object:%s, not valid repo group', full_path, scm_) | |
|
305 | 303 | return False |
|
306 | 304 | except VCSError: |
|
307 | 305 | pass |
@@ -774,5 +772,5 b' def generate_platform_uuid():' | |||
|
774 | 772 | uuid_list = [platform.platform()] |
|
775 | 773 | return hashlib.sha256(':'.join(uuid_list)).hexdigest() |
|
776 | 774 | except Exception as e: |
|
777 |
log.error('Failed to generate host uuid: %s' |
|
|
775 | log.error('Failed to generate host uuid: %s', e) | |
|
778 | 776 | return 'UNDEFINED' |
@@ -2539,8 +2539,8 b' class RepoGroup(Base, BaseModel):' | |||
|
2539 | 2539 | break |
|
2540 | 2540 | if cnt == parents_recursion_limit: |
|
2541 | 2541 | # this will prevent accidental infinit loops |
|
2542 |
log.error |
|
|
2543 |
|
|
|
2542 | log.error('more than %s parents found for group %s, stopping ' | |
|
2543 | 'recursive parent fetching', parents_recursion_limit, self) | |
|
2544 | 2544 | break |
|
2545 | 2545 | |
|
2546 | 2546 | groups.insert(0, gr) |
@@ -241,9 +241,8 b' class SettingsModel(BaseModel):' | |||
|
241 | 241 | region.invalidate() |
|
242 | 242 | |
|
243 | 243 | result = _get_all_settings('rhodecode_settings', key) |
|
244 | log.debug( | |
|
245 | 'Fetching app settings for key: %s took: %.3fs', key, | |
|
246 | inv_context_manager.compute_time) | |
|
244 | log.debug('Fetching app settings for key: %s took: %.3fs', key, | |
|
245 | inv_context_manager.compute_time) | |
|
247 | 246 | |
|
248 | 247 | return result |
|
249 | 248 |
@@ -300,11 +300,11 b' class UserModel(BaseModel):' | |||
|
300 | 300 | |
|
301 | 301 | if updating_user_id: |
|
302 | 302 | log.debug('Checking for existing account in RhodeCode ' |
|
303 |
'database with user_id `%s` ' |
|
|
303 | 'database with user_id `%s` ', updating_user_id) | |
|
304 | 304 | user = User.get(updating_user_id) |
|
305 | 305 | else: |
|
306 | 306 | log.debug('Checking for existing account in RhodeCode ' |
|
307 |
'database with username `%s` ' |
|
|
307 | 'database with username `%s` ', username) | |
|
308 | 308 | user = User.get_by_username(username, case_insensitive=True) |
|
309 | 309 | |
|
310 | 310 | if user is None: |
@@ -626,7 +626,7 b' class UserGroupModel(BaseModel):' | |||
|
626 | 626 | self.remove_user_from_group(gr, user) |
|
627 | 627 | else: |
|
628 | 628 | log.debug('Skipping removal from group %s since it is ' |
|
629 |
'not set to be automatically synchronized' |
|
|
629 | 'not set to be automatically synchronized', gr) | |
|
630 | 630 | |
|
631 | 631 | # now we calculate in which groups user should be == groups params |
|
632 | 632 | owner = User.get_first_super_admin().username |
@@ -647,7 +647,7 b' class UserGroupModel(BaseModel):' | |||
|
647 | 647 | UserGroupModel().add_user_to_group(existing_group, user) |
|
648 | 648 | else: |
|
649 | 649 | log.debug('Skipping addition to group %s since it is ' |
|
650 |
'not set to be automatically synchronized' |
|
|
650 | 'not set to be automatically synchronized', gr) | |
|
651 | 651 | |
|
652 | 652 | def change_groups(self, user, groups): |
|
653 | 653 | """ |
@@ -99,8 +99,8 b' class RhodeCodeAuthPlugin(RhodeCodeExter' | |||
|
99 | 99 | 'extern_type': extern_type, |
|
100 | 100 | } |
|
101 | 101 | |
|
102 |
log.debug('EXTERNAL user: \n%s' |
|
|
103 |
log.info('user `%s` authenticated correctly' |
|
|
102 | log.debug('EXTERNAL user: \n%s', formatted_json(user_attrs)) | |
|
103 | log.info('user `%s` authenticated correctly', user_attrs['username']) | |
|
104 | 104 | |
|
105 | 105 | return user_attrs |
|
106 | 106 |
@@ -61,7 +61,7 b' class Command(object):' | |||
|
61 | 61 | """ |
|
62 | 62 | |
|
63 | 63 | command = cmd + ' ' + ' '.join(args) |
|
64 |
log.debug('Executing %s' |
|
|
64 | log.debug('Executing %s', command) | |
|
65 | 65 | if DEBUG: |
|
66 | 66 | print(command) |
|
67 | 67 | p = Popen(command, shell=True, stdout=PIPE, stderr=PIPE, cwd=self.cwd) |
@@ -57,7 +57,7 b' class Command(object):' | |||
|
57 | 57 | |
|
58 | 58 | command = cmd + ' ' + ' '.join(args) |
|
59 | 59 | if DEBUG: |
|
60 |
log.debug('*** CMD %s ***' |
|
|
60 | log.debug('*** CMD %s ***', command) | |
|
61 | 61 | |
|
62 | 62 | env = dict(os.environ) |
|
63 | 63 | # Delete coverage variables, as they make the test fail for Mercurial |
@@ -69,8 +69,8 b' class Command(object):' | |||
|
69 | 69 | cwd=self.cwd, env=env) |
|
70 | 70 | stdout, stderr = self.process.communicate() |
|
71 | 71 | if DEBUG: |
|
72 |
log.debug('STDOUT:%s' |
|
|
73 |
log.debug('STDERR:%s' |
|
|
72 | log.debug('STDOUT:%s', stdout) | |
|
73 | log.debug('STDERR:%s', stderr) | |
|
74 | 74 | return stdout, stderr |
|
75 | 75 | |
|
76 | 76 | def assert_returncode_success(self): |
General Comments 0
You need to be logged in to leave comments.
Login now