summaryrefslogtreecommitdiff
diff options
context:
space:
mode:
authorJames E. Blair <jeblair@redhat.com>2019-02-12 11:32:11 -0800
committerTobias Henkel <tobias.henkel@bmw.de>2019-02-12 22:14:55 +0100
commitd540ebfe3220064e6d01c7059f98bf5984231422 (patch)
tree1c5e7f0f98f9650aa3d796b80d00f5cf363dd242
parent6d6c69f93e9755b3b812c85ffceb1b830bd75d6f (diff)
Improve event logging in githubconnection
This moves event processing to its own class, so that it's easier to bundle all of the data related to an event along with an event-specific logger. This logs the delivery ID for every line when we're preparing the event. It also logs the start time and queue length as well as the end time, even on error. Change-Id: I941a74ecbdb418cf94537ca9f8f1917a5e38dd33
Notes
Notes (review): Code-Review+2: Monty Taylor <mordred@inaugust.com> Code-Review+2: James E. Blair <corvus@inaugust.com> Workflow+1: James E. Blair <corvus@inaugust.com> Code-Review+2: Tobias Henkel <tobias.henkel@bmw.de> Workflow+1: Tobias Henkel <tobias.henkel@bmw.de> Verified+2: Zuul Submitted-by: Zuul Submitted-at: Tue, 12 Feb 2019 22:02:03 +0000 Reviewed-on: https://review.openstack.org/636429 Project: openstack-infra/zuul Branch: refs/heads/master
-rw-r--r--zuul/driver/github/githubconnection.py172
1 files changed, 104 insertions, 68 deletions
diff --git a/zuul/driver/github/githubconnection.py b/zuul/driver/github/githubconnection.py
index 6cc4c2e..218c82c 100644
--- a/zuul/driver/github/githubconnection.py
+++ b/zuul/driver/github/githubconnection.py
@@ -171,30 +171,37 @@ class GithubGearmanWorker(object):
171 self.gearman.shutdown() 171 self.gearman.shutdown()
172 172
173 173
174class GithubEventConnector(threading.Thread): 174class GithubEventLogAdapter(logging.LoggerAdapter):
175 """Move events from GitHub into the scheduler""" 175 def process(self, msg, kwargs):
176 msg, kwargs = super(GithubEventLogAdapter, self).process(msg, kwargs)
177 msg = '[delivery: %s] %s' % (kwargs['extra']['delivery'], msg)
178 return msg, kwargs
176 179
177 log = logging.getLogger("zuul.GithubEventConnector")
178 180
179 def __init__(self, connection): 181class GithubEventProcessor(object):
180 super(GithubEventConnector, self).__init__() 182 def __init__(self, connector, event_tuple):
181 self.daemon = True 183 self.connector = connector
182 self.connection = connection 184 self.connection = connector.connection
183 self._stopped = False 185 self.ts, self.body, self.event_type, self.delivery = event_tuple
186 logger = logging.getLogger("zuul.GithubEventConnector")
187 self.log = GithubEventLogAdapter(logger, {'delivery': self.delivery})
184 188
185 def stop(self): 189 def run(self):
186 self._stopped = True 190 self.log.debug("Starting event processing, queue length %s",
187 self.connection.addEvent(None) 191 self.connection.getEventQueueSize())
192 try:
193 self._handle_event()
194 finally:
195 self.log.debug("Finished event processing")
188 196
189 def _handleEvent(self): 197 def _handle_event(self):
190 ts, json_body, event_type, delivery = self.connection.getEvent() 198 if self.connector._stopped:
191 if self._stopped:
192 return 199 return
193 200
194 # If there's any installation mapping information in the body then 201 # If there's any installation mapping information in the body then
195 # update the project mapping before any requests are made. 202 # update the project mapping before any requests are made.
196 installation_id = json_body.get('installation', {}).get('id') 203 installation_id = self.body.get('installation', {}).get('id')
197 project_name = json_body.get('repository', {}).get('full_name') 204 project_name = self.body.get('repository', {}).get('full_name')
198 205
199 if installation_id and project_name: 206 if installation_id and project_name:
200 old_id = self.connection.installation_map.get(project_name) 207 old_id = self.connection.installation_map.get(project_name)
@@ -206,29 +213,33 @@ class GithubEventConnector(threading.Thread):
206 self.connection.installation_map[project_name] = installation_id 213 self.connection.installation_map[project_name] = installation_id
207 214
208 try: 215 try:
209 method = getattr(self, '_event_' + event_type) 216 method = getattr(self, '_event_' + self.event_type)
210 except AttributeError: 217 except AttributeError:
211 # TODO(jlk): Gracefully handle event types we don't care about 218 # TODO(jlk): Gracefully handle event types we don't care about
212 # instead of logging an exception. 219 # instead of logging an exception.
213 message = "Unhandled X-Github-Event: {0}".format(event_type) 220 message = "Unhandled X-Github-Event: {0}".format(self.event_type)
214 self.log.debug(message) 221 self.log.debug(message)
215 # Returns empty on unhandled events 222 # Returns empty on unhandled events
216 return 223 return
217 224
225 self.log.debug("Handling %s event", self.event_type)
226
218 try: 227 try:
219 event = method(json_body) 228 event = method()
220 except Exception: 229 except Exception:
221 self.log.exception('Exception when handling event:') 230 self.log.exception('Exception when handling event:')
222 event = None 231 event = None
223 232
224 if event: 233 if event:
225 event.delivery = delivery 234 event.delivery = self.delivery
226 project = self.connection.source.getProject(event.project_name) 235 project = self.connection.source.getProject(event.project_name)
227 if event.change_number: 236 if event.change_number:
228 self.connection._getChange(project, 237 self.connection._getChange(project,
229 event.change_number, 238 event.change_number,
230 event.patch_number, 239 event.patch_number,
231 refresh=True) 240 refresh=True)
241 self.log.debug("Refreshed change %s,%s",
242 event.change_number, event.patch_number)
232 243
233 # If this event references a branch and we're excluding unprotected 244 # If this event references a branch and we're excluding unprotected
234 # branches, we might need to check whether the branch is now 245 # branches, we might need to check whether the branch is now
@@ -237,8 +248,8 @@ class GithubEventConnector(threading.Thread):
237 b = self.connection.getBranch(project.name, event.branch) 248 b = self.connection.getBranch(project.name, event.branch)
238 if b is not None: 249 if b is not None:
239 branch_protected = b.get('protected') 250 branch_protected = b.get('protected')
240 self.connection.checkBranchCache(project, event.branch, 251 self.connection.checkBranchCache(
241 branch_protected) 252 project, event.branch, branch_protected, self.log)
242 event.branch_protected = branch_protected 253 event.branch_protected = branch_protected
243 else: 254 else:
244 # This can happen if the branch was deleted in GitHub. In 255 # This can happen if the branch was deleted in GitHub. In
@@ -251,8 +262,8 @@ class GithubEventConnector(threading.Thread):
251 self.connection.logEvent(event) 262 self.connection.logEvent(event)
252 self.connection.sched.addEvent(event) 263 self.connection.sched.addEvent(event)
253 264
254 def _event_push(self, body): 265 def _event_push(self):
255 base_repo = body.get('repository') 266 base_repo = self.body.get('repository')
256 267
257 event = GithubTriggerEvent() 268 event = GithubTriggerEvent()
258 event.trigger_name = 'github' 269 event.trigger_name = 'github'
@@ -260,10 +271,10 @@ class GithubEventConnector(threading.Thread):
260 event.type = 'push' 271 event.type = 'push'
261 event.branch_updated = True 272 event.branch_updated = True
262 273
263 event.ref = body.get('ref') 274 event.ref = self.body.get('ref')
264 event.oldrev = body.get('before') 275 event.oldrev = self.body.get('before')
265 event.newrev = body.get('after') 276 event.newrev = self.body.get('after')
266 event.commits = body.get('commits') 277 event.commits = self.body.get('commits')
267 278
268 ref_parts = event.ref.split('/', 2) # ie, ['refs', 'heads', 'foo/bar'] 279 ref_parts = event.ref.split('/', 2) # ie, ['refs', 'heads', 'foo/bar']
269 280
@@ -289,20 +300,20 @@ class GithubEventConnector(threading.Thread):
289 # know if branch protection has been disabled before deletion 300 # know if branch protection has been disabled before deletion
290 # of the branch. 301 # of the branch.
291 # FIXME(tobiash): Find a way to handle that case 302 # FIXME(tobiash): Find a way to handle that case
292 self.connection._clearBranchCache(project) 303 self.connection._clearBranchCache(project, self.log)
293 elif event.branch_created: 304 elif event.branch_created:
294 # A new branch never can be protected because that needs to be 305 # A new branch never can be protected because that needs to be
295 # configured after it has been created. 306 # configured after it has been created.
296 self.connection._clearBranchCache(project) 307 self.connection._clearBranchCache(project, self.log)
297 308
298 return event 309 return event
299 310
300 def _event_pull_request(self, body): 311 def _event_pull_request(self):
301 action = body.get('action') 312 action = self.body.get('action')
302 pr_body = body.get('pull_request') 313 pr_body = self.body.get('pull_request')
303 314
304 event = self._pull_request_to_event(pr_body) 315 event = self._pull_request_to_event(pr_body)
305 event.account = self._get_sender(body) 316 event.account = self._get_sender(self.body)
306 317
307 event.type = 'pull_request' 318 event.type = 'pull_request'
308 if action == 'opened': 319 if action == 'opened':
@@ -315,10 +326,10 @@ class GithubEventConnector(threading.Thread):
315 event.action = 'reopened' 326 event.action = 'reopened'
316 elif action == 'labeled': 327 elif action == 'labeled':
317 event.action = 'labeled' 328 event.action = 'labeled'
318 event.label = body['label']['name'] 329 event.label = self.body['label']['name']
319 elif action == 'unlabeled': 330 elif action == 'unlabeled':
320 event.action = 'unlabeled' 331 event.action = 'unlabeled'
321 event.label = body['label']['name'] 332 event.label = self.body['label']['name']
322 elif action == 'edited': 333 elif action == 'edited':
323 event.action = 'edited' 334 event.action = 'edited'
324 else: 335 else:
@@ -326,66 +337,67 @@ class GithubEventConnector(threading.Thread):
326 337
327 return event 338 return event
328 339
329 def _event_issue_comment(self, body): 340 def _event_issue_comment(self):
330 """Handles pull request comments""" 341 """Handles pull request comments"""
331 action = body.get('action') 342 action = self.body.get('action')
332 if action != 'created': 343 if action != 'created':
333 return 344 return
334 if not body.get('issue', {}).get('pull_request'): 345 if not self.body.get('issue', {}).get('pull_request'):
335 # Do not process non-PR issue comment 346 # Do not process non-PR issue comment
336 return 347 return
337 pr_body = self._issue_to_pull_request(body) 348 pr_body = self._issue_to_pull_request(self.body)
338 if pr_body is None: 349 if pr_body is None:
339 return 350 return
340 351
341 event = self._pull_request_to_event(pr_body) 352 event = self._pull_request_to_event(pr_body)
342 event.account = self._get_sender(body) 353 event.account = self._get_sender(self.body)
343 event.comment = body.get('comment').get('body') 354 event.comment = self.body.get('comment').get('body')
344 event.type = 'pull_request' 355 event.type = 'pull_request'
345 event.action = 'comment' 356 event.action = 'comment'
346 return event 357 return event
347 358
348 def _event_pull_request_review(self, body): 359 def _event_pull_request_review(self):
349 """Handles pull request reviews""" 360 """Handles pull request reviews"""
350 pr_body = body.get('pull_request') 361 pr_body = self.body.get('pull_request')
351 if pr_body is None: 362 if pr_body is None:
352 return 363 return
353 364
354 review = body.get('review') 365 review = self.body.get('review')
355 if review is None: 366 if review is None:
356 return 367 return
357 368
358 event = self._pull_request_to_event(pr_body) 369 event = self._pull_request_to_event(pr_body)
359 event.state = review.get('state') 370 event.state = review.get('state')
360 event.account = self._get_sender(body) 371 event.account = self._get_sender(self.body)
361 event.type = 'pull_request_review' 372 event.type = 'pull_request_review'
362 event.action = body.get('action') 373 event.action = self.body.get('action')
363 return event 374 return event
364 375
365 def _event_status(self, body): 376 def _event_status(self):
366 action = body.get('action') 377 action = self.body.get('action')
367 if action == 'pending': 378 if action == 'pending':
368 return 379 return
369 project = body.get('name') 380 project = self.body.get('name')
370 pr_body = self.connection.getPullBySha(body['sha'], project) 381 pr_body = self.connection.getPullBySha(
382 self.body['sha'], project, self.log)
371 if pr_body is None: 383 if pr_body is None:
372 return 384 return
373 385
374 event = self._pull_request_to_event(pr_body) 386 event = self._pull_request_to_event(pr_body)
375 event.account = self._get_sender(body) 387 event.account = self._get_sender(self.body)
376 event.type = 'pull_request' 388 event.type = 'pull_request'
377 event.action = 'status' 389 event.action = 'status'
378 # Github API is silly. Webhook blob sets author data in 390 # Github API is silly. Webhook blob sets author data in
379 # 'sender', but API call to get status puts it in 'creator'. 391 # 'sender', but API call to get status puts it in 'creator'.
380 # Duplicate the data so our code can look in one place 392 # Duplicate the data so our code can look in one place
381 body['creator'] = body['sender'] 393 self.body['creator'] = self.body['sender']
382 event.status = "%s:%s:%s" % _status_as_tuple(body) 394 event.status = "%s:%s:%s" % _status_as_tuple(self.body)
383 return event 395 return event
384 396
385 def _issue_to_pull_request(self, body): 397 def _issue_to_pull_request(self, body):
386 number = body.get('issue').get('number') 398 number = body.get('issue').get('number')
387 project_name = body.get('repository').get('full_name') 399 project_name = body.get('repository').get('full_name')
388 pr_body = self.connection.getPull(project_name, number) 400 pr_body = self.connection.getPull(project_name, number, self.log)
389 if pr_body is None: 401 if pr_body is None:
390 self.log.debug('Pull request #%s not found in project %s' % 402 self.log.debug('Pull request #%s not found in project %s' %
391 (number, project_name)) 403 (number, project_name))
@@ -417,14 +429,33 @@ class GithubEventConnector(threading.Thread):
417 if login: 429 if login:
418 # TODO(tobiash): it might be better to plumb in the installation id 430 # TODO(tobiash): it might be better to plumb in the installation id
419 project = body.get('repository', {}).get('full_name') 431 project = body.get('repository', {}).get('full_name')
420 return self.connection.getUser(login, project) 432 user = self.connection.getUser(login, project)
433 self.log.debug("Got user %s", user)
434 return user
435
436
437class GithubEventConnector(threading.Thread):
438 """Move events from GitHub into the scheduler"""
439
440 log = logging.getLogger("zuul.GithubEventConnector")
441
442 def __init__(self, connection):
443 super(GithubEventConnector, self).__init__()
444 self.daemon = True
445 self.connection = connection
446 self._stopped = False
447
448 def stop(self):
449 self._stopped = True
450 self.connection.addEvent(None)
421 451
422 def run(self): 452 def run(self):
423 while True: 453 while True:
424 if self._stopped: 454 if self._stopped:
425 return 455 return
426 try: 456 try:
427 self._handleEvent() 457 data = self.connection.getEvent()
458 GithubEventProcessor(self, data).run()
428 except Exception: 459 except Exception:
429 self.log.exception("Exception moving GitHub event:") 460 self.log.exception("Exception moving GitHub event:")
430 finally: 461 finally:
@@ -754,6 +785,9 @@ class GithubConnection(BaseConnection):
754 def getEvent(self): 785 def getEvent(self):
755 return self.event_queue.get() 786 return self.event_queue.get()
756 787
788 def getEventQueueSize(self):
789 return self.event_queue.qsize()
790
757 def eventDone(self): 791 def eventDone(self):
758 self.event_queue.task_done() 792 self.event_queue.task_done()
759 793
@@ -1065,7 +1099,9 @@ class GithubConnection(BaseConnection):
1065 def getPullUrl(self, project, number): 1099 def getPullUrl(self, project, number):
1066 return '%s/pull/%s' % (self.getGitwebUrl(project), number) 1100 return '%s/pull/%s' % (self.getGitwebUrl(project), number)
1067 1101
1068 def getPull(self, project_name, number): 1102 def getPull(self, project_name, number, log=None):
1103 if log is None:
1104 log = self.log
1069 github = self.getGithubClient(project_name) 1105 github = self.getGithubClient(project_name)
1070 owner, proj = project_name.split('/') 1106 owner, proj = project_name.split('/')
1071 for retry in range(5): 1107 for retry in range(5):
@@ -1089,7 +1125,7 @@ class GithubConnection(BaseConnection):
1089 pr['files'] = [] 1125 pr['files'] = []
1090 1126
1091 pr['labels'] = [l.name for l in issueobj.labels()] 1127 pr['labels'] = [l.name for l in issueobj.labels()]
1092 self.log.debug('Got PR %s#%s', project_name, number) 1128 log.debug('Got PR %s#%s', project_name, number)
1093 self.log_rate_limit(self.log, github) 1129 self.log_rate_limit(self.log, github)
1094 return pr 1130 return pr
1095 1131
@@ -1125,7 +1161,7 @@ class GithubConnection(BaseConnection):
1125 1161
1126 return True 1162 return True
1127 1163
1128 def getPullBySha(self, sha, project): 1164 def getPullBySha(self, sha, project, log):
1129 pulls = [] 1165 pulls = []
1130 owner, project = project.split('/') 1166 owner, project = project.split('/')
1131 github = self.getGithubClient("%s/%s" % (owner, project)) 1167 github = self.getGithubClient("%s/%s" % (owner, project))
@@ -1137,7 +1173,7 @@ class GithubConnection(BaseConnection):
1137 continue 1173 continue
1138 pulls.append(pr.as_dict()) 1174 pulls.append(pr.as_dict())
1139 1175
1140 self.log.debug('Got PR on project %s for sha %s', project, sha) 1176 log.debug('Got PR on project %s for sha %s', project, sha)
1141 self.log_rate_limit(self.log, github) 1177 self.log_rate_limit(self.log, github)
1142 if len(pulls) > 1: 1178 if len(pulls) > 1:
1143 raise Exception('Multiple pulls found with head sha %s' % sha) 1179 raise Exception('Multiple pulls found with head sha %s' % sha)
@@ -1433,8 +1469,8 @@ class GithubConnection(BaseConnection):
1433 log.debug('GitHub API rate limit remaining: %s reset: %s', 1469 log.debug('GitHub API rate limit remaining: %s reset: %s',
1434 remaining, reset) 1470 remaining, reset)
1435 1471
1436 def _clearBranchCache(self, project): 1472 def _clearBranchCache(self, project, log):
1437 self.log.debug("Clearing branch cache for %s", project.name) 1473 log.debug("Clearing branch cache for %s", project.name)
1438 for cache in [ 1474 for cache in [
1439 self._project_branch_cache_exclude_unprotected, 1475 self._project_branch_cache_exclude_unprotected,
1440 self._project_branch_cache_include_unprotected, 1476 self._project_branch_cache_include_unprotected,
@@ -1444,7 +1480,7 @@ class GithubConnection(BaseConnection):
1444 except KeyError: 1480 except KeyError:
1445 pass 1481 pass
1446 1482
1447 def checkBranchCache(self, project, branch, protected): 1483 def checkBranchCache(self, project, branch, protected, log):
1448 # If the branch appears in the exclude_unprotected cache but 1484 # If the branch appears in the exclude_unprotected cache but
1449 # is unprotected, clear the exclude cache. 1485 # is unprotected, clear the exclude cache.
1450 1486
@@ -1457,16 +1493,16 @@ class GithubConnection(BaseConnection):
1457 cache = self._project_branch_cache_exclude_unprotected 1493 cache = self._project_branch_cache_exclude_unprotected
1458 branches = cache.get(project.name, []) 1494 branches = cache.get(project.name, [])
1459 if (branch in branches) and (not protected): 1495 if (branch in branches) and (not protected):
1460 self.log.debug("Clearing protected branch cache for %s", 1496 log.debug("Clearing protected branch cache for %s",
1461 project.name) 1497 project.name)
1462 try: 1498 try:
1463 del cache[project.name] 1499 del cache[project.name]
1464 except KeyError: 1500 except KeyError:
1465 pass 1501 pass
1466 return 1502 return
1467 if (branch not in branches) and (protected): 1503 if (branch not in branches) and (protected):
1468 self.log.debug("Clearing protected branch cache for %s", 1504 log.debug("Clearing protected branch cache for %s",
1469 project.name) 1505 project.name)
1470 try: 1506 try:
1471 del cache[project.name] 1507 del cache[project.name]
1472 except KeyError: 1508 except KeyError: