Time out console log downloads from Jenkins

Summary: Put a hard limit on how long we're willing to spend downloading a console log from Jenkins.

Test Plan: Added a test

Reviewers: vishal, kylec

Reviewed By: vishal, kylec

Subscribers: changesbot, cf, ar, kylec

Differential Revision: https://tails.corp.dropbox.com/D98449

changes/backends/jenkins/builder.py

@@ -46,6 +46,8 @@
 
 ID_XML_RE = re.compile(r'<id>(\d+)</id>')
 
+LOG_SYNC_TIMEOUT_SECS = 30
+
 
 class NotFound(Exception):
     pass
@@ -270,6 +272,8 @@ def _sync_log(self, jobstep, name, job_name, build_no):
             build=build_no,
         )
 
+        start_time = time.time()
+
         session = self.http_session
         with closing(session.get(url, params={'start': offset}, stream=True, timeout=15)) as resp:
             log_length = int(resp.headers['X-Text-Size'])
@@ -296,6 +300,26 @@ def _sync_log(self, jobstep, name, job_name, build_no):
                 })
                 offset += chunk_size
 
+                if time.time() > start_time + LOG_SYNC_TIMEOUT_SECS:
+                    warning = ("\nTRUNCATED LOG: TOOK TOO LONG TO DOWNLOAD FROM JENKINS. SEE FULL LOG AT "
+                               "{base}/job/{job}/{build}/consoleText\n").format(
+                                   base=jobstep.data['master'],
+                                   job=job_name,
+                                   build=build_no,
+                               )
+                    create_or_update(LogChunk, where={
+                        'source': logsource,
+                        'offset': offset,
+                    }, values={
+                        'job': job,
+                        'project': job.project,
+                        'size': len(warning),
+                        'text': warning,
+                    })
+                    offset += chunk_size
+                    self.logger.warning('log download took too long')
+                    break
+
             # Jenkins will suggest to us that there is more data when the job has
             # yet to complete
             has_more = resp.headers.get('X-More-Data') == 'true'

setup.py

@@ -20,7 +20,7 @@
     'pytest-cov>=1.6,<1.7',
     'pytest-timeout>=0.3,<0.4',
     'pytest-xdist>=1.9,<1.10',
-    'responses>=0.2.0,<0.3.0',
+    'responses>=0.3.0,<0.4.0',
     'unittest2>=0.5.1,<0.6.0',
     'moto>=0.3.0,<0.4.0',
 ]

tests/changes/backends/jenkins/test_builder.py

@@ -5,6 +5,7 @@
 import os.path
 import responses
 import pytest
+import time
 
 from datetime import datetime
 from flask import current_app
@@ -414,6 +415,54 @@ def test_failed_result(self):
         assert step.result == Result.failed
         assert step.date_finished is not None
 
+    @responses.activate
+    @mock.patch('changes.backends.jenkins.builder.time')
+    def test_result_slow_log(self, mock_time):
+        mock_time.time.return_value = time.time()
+
+        def log_text_callback(request):
+            # Zoom 10 minutes into the future; this should cause the console
+            # downloading code to bail
+            mock_time.time.return_value += 10 * 60
+            data = "log\n" * 10000
+            return (200, {'X-Text-Size': str(len(data))}, data)
+
+        responses.add(
+            responses.GET, 'http://jenkins.example.com/job/server/2/api/json/',
+            body=self.load_fixture('fixtures/GET/job_details_failed.json'))
+        responses.add_callback(
+            responses.GET, 'http://jenkins.example.com/job/server/2/logText/progressiveText/?start=0',
+            match_querystring=True,
+            callback=log_text_callback)
+        responses.add(
+            responses.GET, 'http://jenkins.example.com/computer/server-ubuntu-10.04%20(ami-746cf244)%20(i-836023b7)/config.xml',
+            body=self.load_fixture('fixtures/GET/node_config.xml'))
+
+        build = self.create_build(self.project)
+        job = self.create_job(
+            build=build,
+            id=UUID('81d1596fd4d642f4a6bdf86c45e014e8'),
+            data={
+                'build_no': 2,
+                'item_id': 13,
+                'job_name': 'server',
+                'queued': False,
+                'master': 'http://jenkins.example.com',
+            },
+        )
+        phase = self.create_jobphase(job)
+        step = self.create_jobstep(phase, data=job.data)
+
+        builder = self.get_builder()
+        builder.sync_step(step)
+
+        assert len(step.logsources) == 1
+        chunks = list(LogChunk.query.filter_by(
+            source=step.logsources[0],
+        ).order_by(LogChunk.offset.asc()))
+        assert len(chunks) == 2
+        assert "TOO LONG TO DOWNLOAD" in chunks[1].text
+
 
 class SyncGenericResultsTest(BaseTestCase):
     @responses.activate