From f62d428f3b33aaa8d9dc0cdae3cb8563289b5c10 Mon Sep 17 00:00:00 2001 From: "James E. Blair" Date: Mon, 31 Dec 2012 17:01:50 -0800 Subject: [PATCH] Fix exception calculating run time for lost builds. When a build is reported as lost, it has no start_time, so the code that calculated the run-time for statsd threw an exception. Correct that by only calculating the run time for jobs that have really completed. Add debug lines to onBuild* that would have helped diagnose this. Keep track of the throwaway threads that are used to report LOST builds so that the test suite can more correctly know when the system is settled. Add a test case for a single non-existent post job. Add STATSD_* env variables in tox to make sure that the statsd code paths are executed by tests. Change-Id: I339443cbad7b0858d70e9180d63dfb701b8eaee9 Reviewed-on: https://review.openstack.org/18792 Reviewed-by: Clark Boylan Approved: Jeremy Stanley Reviewed-by: Jeremy Stanley Tested-by: Jenkins --- tests/test_scheduler.py | 28 +++++++++++++++++++++++++++- tox.ini | 3 +++ zuul/launcher/jenkins.py | 5 +++++ zuul/scheduler.py | 5 ++++- 4 files changed, 39 insertions(+), 2 deletions(-) diff --git a/tests/test_scheduler.py b/tests/test_scheduler.py index cbc006ea38..c199345d8f 100644 --- a/tests/test_scheduler.py +++ b/tests/test_scheduler.py @@ -696,6 +696,7 @@ class testScheduler(unittest.TestCase): if (self.sched.trigger_event_queue.empty() and self.sched.result_event_queue.empty() and self.fake_gerrit.event_queue.empty() and + len(self.jenkins.lost_threads) == 0 and self.fake_jenkins.fakeAllWaiting()): self.sched.queue_lock.release() self.log.debug("...settled.") @@ -712,7 +713,8 @@ class testScheduler(unittest.TestCase): for pipeline in self.sched.pipelines.values(): for queue in pipeline.queues: if len(queue.queue) != 0: - print 'queue', queue.queue + print 'pipeline %s queue %s contents %s' % ( + pipeline.name, queue.name, queue.queue) assert len(queue.queue) == 0 if len(queue.severed_heads) != 0: print 'heads', queue.severed_heads @@ -1635,3 +1637,27 @@ class testScheduler(unittest.TestCase): assert A.data['status'] == 'MERGED' assert A.reported == 2 self.assertEmptyQueues() + + def test_single_nonexistent_post_job(self): + "Test launching a single post job that doesn't exist" + self.fake_jenkins.nonexistent_jobs.append('project-post') + self.jenkins.launch_retry_timeout = 0.1 + + e = { + "type": "ref-updated", + "submitter": { + "name": "User Name", + }, + "refUpdate": { + "oldRev": "90f173846e3af9154517b88543ffbd1691f31366", + "newRev": "d479a0bfcb34da57a31adb2a595c0cf687812543", + "refName": "master", + "project": "org/project", + } + } + self.fake_gerrit.addEvent(e) + self.waitUntilSettled() + + jobs = self.fake_jenkins.job_history + assert len(jobs) == 0 + self.assertEmptyQueues() diff --git a/tox.ini b/tox.ini index 198c01c1a3..adddba8d30 100644 --- a/tox.ini +++ b/tox.ini @@ -2,6 +2,9 @@ envlist = pep8, pyflakes, py27 [testenv] +# Set STATSD env variables so that statsd code paths are tested. +setenv = STATSD_HOST=localhost + STATSD_PORT=8125 deps = -r{toxinidir}/tools/pip-requires -r{toxinidir}/tools/test-requires commands = nosetests {posargs} diff --git a/zuul/launcher/jenkins.py b/zuul/launcher/jenkins.py index 1841a92de2..ee73f8ae2b 100644 --- a/zuul/launcher/jenkins.py +++ b/zuul/launcher/jenkins.py @@ -219,6 +219,9 @@ class Jenkins(object): self.callback_thread.start() self.cleanup_thread = JenkinsCleanup(self) self.cleanup_thread.start() + # Keep track of threads that will report a lost build in the future, + # in aid of testing + self.lost_threads = [] def stop(self): self.cleanup_thread.stop() @@ -326,6 +329,7 @@ class Jenkins(object): # so that the change will get dropped. t = threading.Thread(target=self.declareBuildLost, args=(build,)) + self.lost_threads.append(t) t.start() return build @@ -333,6 +337,7 @@ class Jenkins(object): # Call this from a new thread to invoke onBuildCompleted from # a thread that has the queue lock. self.onBuildCompleted(build.uuid, 'LOST', None, None) + self.lost_threads.remove(threading.currentThread()) def findBuildInQueue(self, build): for item in self.jenkins.get_queue_info(): diff --git a/zuul/scheduler.py b/zuul/scheduler.py index 83487deb22..7d7fb510b5 100644 --- a/zuul/scheduler.py +++ b/zuul/scheduler.py @@ -224,6 +224,7 @@ class Scheduler(threading.Thread): self.trigger_event_queue.put(event) self.queue_lock.release() self.wake_event.set() + self.log.debug("Done adding trigger event: %s" % event) def onBuildStarted(self, build): self.log.debug("Adding start event for build: %s" % build) @@ -232,20 +233,22 @@ class Scheduler(threading.Thread): self.result_event_queue.put(('started', build)) self.queue_lock.release() self.wake_event.set() + self.log.debug("Done adding start event for build: %s" % build) def onBuildCompleted(self, build): self.log.debug("Adding complete event for build: %s" % build) build.end_time = time.time() if statsd: - dt = int((build.end_time - build.start_time) * 1000) key = 'zuul.job.%s' % build.job.name if build.result in ['SUCCESS', 'FAILURE']: + dt = int((build.end_time - build.start_time) * 1000) statsd.timing(key, dt) statsd.incr(key) self.queue_lock.acquire() self.result_event_queue.put(('completed', build)) self.queue_lock.release() self.wake_event.set() + self.log.debug("Done adding complete event for build: %s" % build) def reconfigure(self, config): self.log.debug("Prepare to reconfigure")