Record and report time for trigger events

Sometimes, e.g. during reconfiguration, it can take quite some time
between the trigger event and when a change is enqueued.

This change allows tracking the time it takes from receiving the event
until it is processed by the scheduler.

Change-Id: I347acf56bc8d7671d96f6be444c71902563684be

doc/source/admin/drivers/mqtt.rst

@@ -115,6 +115,7 @@ Here is an example of a start message:
     'branch': 'master',
     'change_url': 'https://gerrit.example.com/r/3',
     'message': 'Starting check jobs.',
+    'trigger_time': '1524801056.2545864',
     'enqueue_time': '1524801093.5689457',
     'change': '3',
     'patchset': '1',
@@ -142,6 +143,7 @@ Here is an example of a success message:
     'branch': 'master',
     'change_url': 'https://gerrit.example.com/r/3',
     'message': 'Build succeeded.',
+    'trigger_time': '1524801056.2545864',
     'enqueue_time': '1524801093.5689457',
     'change': '3',
     'patchset': '1',

tests/unit/test_connection.py

@@ -499,6 +499,7 @@ class TestMQTTConnection(ZuulTestCase):
         self.assertIn('execute_time', test_job)
         self.assertIn('timestamp', mqtt_payload)
         self.assertIn('enqueue_time', mqtt_payload)
+        self.assertIn('trigger_time', mqtt_payload)
         self.assertEquals(dependent_test_job['dependencies'], ['test'])
 
     def test_mqtt_invalid_topic(self):

zuul/driver/gerrit/gerritconnection.py

@@ -72,6 +72,7 @@ class GerritEventConnector(threading.Thread):
         now = time.time()
         time.sleep(max((ts + self.delay) - now, 0.0))
         event = GerritTriggerEvent()
+        event.timestamp = ts
 
         # Gerrit events don't have an event id that could be used to globally
         # identify this event in the system so we have to generate one.

zuul/driver/git/gitconnection.py

@@ -80,6 +80,7 @@ class GitWatcher(threading.Thread):
         for pevent in partial_events:
             event = GitTriggerEvent()
             event.type = 'ref-updated'
+            event.timestamp = time.time()
             event.project_hostname = self.git_connection.canonical_hostname
             event.project_name = project
             for attr in ('ref', 'oldrev', 'newrev', 'branch_created',

zuul/driver/github/githubconnection.py

@@ -386,6 +386,7 @@ class GithubEventProcessor(object):
             with self.connection.get_request_lock(installation_id):
                 event.delivery = self.delivery
                 event.zuul_event_id = self.delivery
+                event.timestamp = self.ts
                 project = self.connection.source.getProject(event.project_name)
                 if event.change_number:
                     self.connection._getChange(project,

zuul/driver/mqtt/mqttreporter.py

@@ -43,6 +43,7 @@ class MQTTReporter(BaseReporter):
             'ref': getattr(item.change, 'ref', ''),
             'message': self._formatItemReport(
                 item, with_jobs=False),
+            'trigger_time': item.event.timestamp,
             'enqueue_time': item.enqueue_time,
             'buildset': {
                 'uuid': item.current_build_set.uuid,

zuul/driver/pagure/pagureconnection.py

@@ -231,6 +231,7 @@ class PagureEventConnector(threading.Thread):
             event = None
 
         if event:
+            event.timestamp = ts
             if event.change_number:
                 project = self.connection.source.getProject(event.project_name)
                 self.connection._getChange(project,

zuul/driver/timer/__init__.py

@@ -15,6 +15,7 @@
 # under the License.
 
 import logging
+import time
 from uuid import uuid4
 
 from apscheduler.schedulers.background import BackgroundScheduler
@@ -100,6 +101,7 @@ class TimerDriver(Driver, TriggerInterface):
                 event.ref = 'refs/heads/%s' % branch
                 event.branch = branch
                 event.zuul_event_id = str(uuid4().hex)
+                event.timestamp = time.time()
                 log = get_annotated_logger(self.log, event)
                 log.debug("Adding event")
                 self.sched.addEvent(event)

zuul/driver/zuul/__init__.py

@@ -13,6 +13,7 @@
 # under the License.
 
 import logging
+import time
 from uuid import uuid4
 
 from zuul.driver import Driver, TriggerInterface
@@ -93,6 +94,7 @@ class ZuulDriver(Driver, TriggerInterface):
         event.patch_number = change.patchset
         event.ref = change.ref
         event.zuul_event_id = str(uuid4().hex)
+        event.timestamp = time.time()
         self.sched.addEvent(event)
 
     def _createParentChangeEnqueuedEvents(self, change, pipeline, tenant,

zuul/model.py

@@ -3147,6 +3147,7 @@ class TriggerEvent(object):
         self.forced_pipeline = None
         # For logging
         self.zuul_event_id = None
+        self.timestamp = None
 
     @property
     def canonical_project_name(self):

zuul/rpclistener.py

@@ -15,6 +15,7 @@
 
 import json
 import logging
+import time
 
 from zuul import model
 from zuul.connection import BaseConnection
@@ -151,6 +152,7 @@ class RPCListener(object):
     def _common_enqueue(self, job):
         args = json.loads(job.arguments)
         event = model.TriggerEvent()
+        event.timestamp = time.time()
         errors = ''
         tenant = None
         project = None