Browse Source

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
James E. Blair 2 months ago
parent
commit
d540ebfe32
No account linked to committer's email address
1 changed files with 104 additions and 68 deletions
  1. 104
    68
      zuul/driver/github/githubconnection.py

+ 104
- 68
zuul/driver/github/githubconnection.py View File

@@ -171,30 +171,37 @@ class GithubGearmanWorker(object):
171 171
         self.gearman.shutdown()
172 172
 
173 173
 
174
-class GithubEventConnector(threading.Thread):
175
-    """Move events from GitHub into the scheduler"""
174
+class GithubEventLogAdapter(logging.LoggerAdapter):
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):
180
-        super(GithubEventConnector, self).__init__()
181
-        self.daemon = True
182
-        self.connection = connection
183
-        self._stopped = False
181
+class GithubEventProcessor(object):
182
+    def __init__(self, connector, event_tuple):
183
+        self.connector = connector
184
+        self.connection = connector.connection
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):
186
-        self._stopped = True
187
-        self.connection.addEvent(None)
189
+    def run(self):
190
+        self.log.debug("Starting event processing, queue length %s",
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):
190
-        ts, json_body, event_type, delivery = self.connection.getEvent()
191
-        if self._stopped:
197
+    def _handle_event(self):
198
+        if self.connector._stopped:
192 199
             return
193 200
 
194 201
         # If there's any installation mapping information in the body then
195 202
         # update the project mapping before any requests are made.
196
-        installation_id = json_body.get('installation', {}).get('id')
197
-        project_name = json_body.get('repository', {}).get('full_name')
203
+        installation_id = self.body.get('installation', {}).get('id')
204
+        project_name = self.body.get('repository', {}).get('full_name')
198 205
 
199 206
         if installation_id and project_name:
200 207
             old_id = self.connection.installation_map.get(project_name)
@@ -206,29 +213,33 @@ class GithubEventConnector(threading.Thread):
206 213
             self.connection.installation_map[project_name] = installation_id
207 214
 
208 215
         try:
209
-            method = getattr(self, '_event_' + event_type)
216
+            method = getattr(self, '_event_' + self.event_type)
210 217
         except AttributeError:
211 218
             # TODO(jlk): Gracefully handle event types we don't care about
212 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 221
             self.log.debug(message)
215 222
             # Returns empty on unhandled events
216 223
             return
217 224
 
225
+        self.log.debug("Handling %s event", self.event_type)
226
+
218 227
         try:
219
-            event = method(json_body)
228
+            event = method()
220 229
         except Exception:
221 230
             self.log.exception('Exception when handling event:')
222 231
             event = None
223 232
 
224 233
         if event:
225
-            event.delivery = delivery
234
+            event.delivery = self.delivery
226 235
             project = self.connection.source.getProject(event.project_name)
227 236
             if event.change_number:
228 237
                 self.connection._getChange(project,
229 238
                                            event.change_number,
230 239
                                            event.patch_number,
231 240
                                            refresh=True)
241
+                self.log.debug("Refreshed change %s,%s",
242
+                               event.change_number, event.patch_number)
232 243
 
233 244
             # If this event references a branch and we're excluding unprotected
234 245
             # branches, we might need to check whether the branch is now
@@ -237,8 +248,8 @@ class GithubEventConnector(threading.Thread):
237 248
                 b = self.connection.getBranch(project.name, event.branch)
238 249
                 if b is not None:
239 250
                     branch_protected = b.get('protected')
240
-                    self.connection.checkBranchCache(project, event.branch,
241
-                                                     branch_protected)
251
+                    self.connection.checkBranchCache(
252
+                        project, event.branch, branch_protected, self.log)
242 253
                     event.branch_protected = branch_protected
243 254
                 else:
244 255
                     # This can happen if the branch was deleted in GitHub. In
@@ -251,8 +262,8 @@ class GithubEventConnector(threading.Thread):
251 262
             self.connection.logEvent(event)
252 263
             self.connection.sched.addEvent(event)
253 264
 
254
-    def _event_push(self, body):
255
-        base_repo = body.get('repository')
265
+    def _event_push(self):
266
+        base_repo = self.body.get('repository')
256 267
 
257 268
         event = GithubTriggerEvent()
258 269
         event.trigger_name = 'github'
@@ -260,10 +271,10 @@ class GithubEventConnector(threading.Thread):
260 271
         event.type = 'push'
261 272
         event.branch_updated = True
262 273
 
263
-        event.ref = body.get('ref')
264
-        event.oldrev = body.get('before')
265
-        event.newrev = body.get('after')
266
-        event.commits = body.get('commits')
274
+        event.ref = self.body.get('ref')
275
+        event.oldrev = self.body.get('before')
276
+        event.newrev = self.body.get('after')
277
+        event.commits = self.body.get('commits')
267 278
 
268 279
         ref_parts = event.ref.split('/', 2)  # ie, ['refs', 'heads', 'foo/bar']
269 280
 
@@ -289,20 +300,20 @@ class GithubEventConnector(threading.Thread):
289 300
                 # know if branch protection has been disabled before deletion
290 301
                 # of the branch.
291 302
                 # FIXME(tobiash): Find a way to handle that case
292
-                self.connection._clearBranchCache(project)
303
+                self.connection._clearBranchCache(project, self.log)
293 304
             elif event.branch_created:
294 305
                 # A new branch never can be protected because that needs to be
295 306
                 # configured after it has been created.
296
-                self.connection._clearBranchCache(project)
307
+                self.connection._clearBranchCache(project, self.log)
297 308
 
298 309
         return event
299 310
 
300
-    def _event_pull_request(self, body):
301
-        action = body.get('action')
302
-        pr_body = body.get('pull_request')
311
+    def _event_pull_request(self):
312
+        action = self.body.get('action')
313
+        pr_body = self.body.get('pull_request')
303 314
 
304 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 318
         event.type = 'pull_request'
308 319
         if action == 'opened':
@@ -315,10 +326,10 @@ class GithubEventConnector(threading.Thread):
315 326
             event.action = 'reopened'
316 327
         elif action == 'labeled':
317 328
             event.action = 'labeled'
318
-            event.label = body['label']['name']
329
+            event.label = self.body['label']['name']
319 330
         elif action == 'unlabeled':
320 331
             event.action = 'unlabeled'
321
-            event.label = body['label']['name']
332
+            event.label = self.body['label']['name']
322 333
         elif action == 'edited':
323 334
             event.action = 'edited'
324 335
         else:
@@ -326,66 +337,67 @@ class GithubEventConnector(threading.Thread):
326 337
 
327 338
         return event
328 339
 
329
-    def _event_issue_comment(self, body):
340
+    def _event_issue_comment(self):
330 341
         """Handles pull request comments"""
331
-        action = body.get('action')
342
+        action = self.body.get('action')
332 343
         if action != 'created':
333 344
             return
334
-        if not body.get('issue', {}).get('pull_request'):
345
+        if not self.body.get('issue', {}).get('pull_request'):
335 346
             # Do not process non-PR issue comment
336 347
             return
337
-        pr_body = self._issue_to_pull_request(body)
348
+        pr_body = self._issue_to_pull_request(self.body)
338 349
         if pr_body is None:
339 350
             return
340 351
 
341 352
         event = self._pull_request_to_event(pr_body)
342
-        event.account = self._get_sender(body)
343
-        event.comment = body.get('comment').get('body')
353
+        event.account = self._get_sender(self.body)
354
+        event.comment = self.body.get('comment').get('body')
344 355
         event.type = 'pull_request'
345 356
         event.action = 'comment'
346 357
         return event
347 358
 
348
-    def _event_pull_request_review(self, body):
359
+    def _event_pull_request_review(self):
349 360
         """Handles pull request reviews"""
350
-        pr_body = body.get('pull_request')
361
+        pr_body = self.body.get('pull_request')
351 362
         if pr_body is None:
352 363
             return
353 364
 
354
-        review = body.get('review')
365
+        review = self.body.get('review')
355 366
         if review is None:
356 367
             return
357 368
 
358 369
         event = self._pull_request_to_event(pr_body)
359 370
         event.state = review.get('state')
360
-        event.account = self._get_sender(body)
371
+        event.account = self._get_sender(self.body)
361 372
         event.type = 'pull_request_review'
362
-        event.action = body.get('action')
373
+        event.action = self.body.get('action')
363 374
         return event
364 375
 
365
-    def _event_status(self, body):
366
-        action = body.get('action')
376
+    def _event_status(self):
377
+        action = self.body.get('action')
367 378
         if action == 'pending':
368 379
             return
369
-        project = body.get('name')
370
-        pr_body = self.connection.getPullBySha(body['sha'], project)
380
+        project = self.body.get('name')
381
+        pr_body = self.connection.getPullBySha(
382
+            self.body['sha'], project, self.log)
371 383
         if pr_body is None:
372 384
             return
373 385
 
374 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 388
         event.type = 'pull_request'
377 389
         event.action = 'status'
378 390
         # Github API is silly. Webhook blob sets author data in
379 391
         # 'sender', but API call to get status puts it in 'creator'.
380 392
         # Duplicate the data so our code can look in one place
381
-        body['creator'] = body['sender']
382
-        event.status = "%s:%s:%s" % _status_as_tuple(body)
393
+        self.body['creator'] = self.body['sender']
394
+        event.status = "%s:%s:%s" % _status_as_tuple(self.body)
383 395
         return event
384 396
 
385 397
     def _issue_to_pull_request(self, body):
386 398
         number = body.get('issue').get('number')
387 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 401
         if pr_body is None:
390 402
             self.log.debug('Pull request #%s not found in project %s' %
391 403
                            (number, project_name))
@@ -417,14 +429,33 @@ class GithubEventConnector(threading.Thread):
417 429
         if login:
418 430
             # TODO(tobiash): it might be better to plumb in the installation id
419 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
+
437
+class 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 452
     def run(self):
423 453
         while True:
424 454
             if self._stopped:
425 455
                 return
426 456
             try:
427
-                self._handleEvent()
457
+                data = self.connection.getEvent()
458
+                GithubEventProcessor(self, data).run()
428 459
             except Exception:
429 460
                 self.log.exception("Exception moving GitHub event:")
430 461
             finally:
@@ -754,6 +785,9 @@ class GithubConnection(BaseConnection):
754 785
     def getEvent(self):
755 786
         return self.event_queue.get()
756 787
 
788
+    def getEventQueueSize(self):
789
+        return self.event_queue.qsize()
790
+
757 791
     def eventDone(self):
758 792
         self.event_queue.task_done()
759 793
 
@@ -1065,7 +1099,9 @@ class GithubConnection(BaseConnection):
1065 1099
     def getPullUrl(self, project, number):
1066 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 1105
         github = self.getGithubClient(project_name)
1070 1106
         owner, proj = project_name.split('/')
1071 1107
         for retry in range(5):
@@ -1089,7 +1125,7 @@ class GithubConnection(BaseConnection):
1089 1125
             pr['files'] = []
1090 1126
 
1091 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 1129
         self.log_rate_limit(self.log, github)
1094 1130
         return pr
1095 1131
 
@@ -1125,7 +1161,7 @@ class GithubConnection(BaseConnection):
1125 1161
 
1126 1162
         return True
1127 1163
 
1128
-    def getPullBySha(self, sha, project):
1164
+    def getPullBySha(self, sha, project, log):
1129 1165
         pulls = []
1130 1166
         owner, project = project.split('/')
1131 1167
         github = self.getGithubClient("%s/%s" % (owner, project))
@@ -1137,7 +1173,7 @@ class GithubConnection(BaseConnection):
1137 1173
                 continue
1138 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 1177
         self.log_rate_limit(self.log, github)
1142 1178
         if len(pulls) > 1:
1143 1179
             raise Exception('Multiple pulls found with head sha %s' % sha)
@@ -1433,8 +1469,8 @@ class GithubConnection(BaseConnection):
1433 1469
             log.debug('GitHub API rate limit remaining: %s reset: %s',
1434 1470
                       remaining, reset)
1435 1471
 
1436
-    def _clearBranchCache(self, project):
1437
-        self.log.debug("Clearing branch cache for %s", project.name)
1472
+    def _clearBranchCache(self, project, log):
1473
+        log.debug("Clearing branch cache for %s", project.name)
1438 1474
         for cache in [
1439 1475
                 self._project_branch_cache_exclude_unprotected,
1440 1476
                 self._project_branch_cache_include_unprotected,
@@ -1444,7 +1480,7 @@ class GithubConnection(BaseConnection):
1444 1480
             except KeyError:
1445 1481
                 pass
1446 1482
 
1447
-    def checkBranchCache(self, project, branch, protected):
1483
+    def checkBranchCache(self, project, branch, protected, log):
1448 1484
         # If the branch appears in the exclude_unprotected cache but
1449 1485
         # is unprotected, clear the exclude cache.
1450 1486
 
@@ -1457,16 +1493,16 @@ class GithubConnection(BaseConnection):
1457 1493
         cache = self._project_branch_cache_exclude_unprotected
1458 1494
         branches = cache.get(project.name, [])
1459 1495
         if (branch in branches) and (not protected):
1460
-            self.log.debug("Clearing protected branch cache for %s",
1461
-                           project.name)
1496
+            log.debug("Clearing protected branch cache for %s",
1497
+                      project.name)
1462 1498
             try:
1463 1499
                 del cache[project.name]
1464 1500
             except KeyError:
1465 1501
                 pass
1466 1502
             return
1467 1503
         if (branch not in branches) and (protected):
1468
-            self.log.debug("Clearing protected branch cache for %s",
1469
-                           project.name)
1504
+            log.debug("Clearing protected branch cache for %s",
1505
+                      project.name)
1470 1506
             try:
1471 1507
                 del cache[project.name]
1472 1508
             except KeyError:

Loading…
Cancel
Save