Add timeouts to the actual http calls in gerrit_util.py

When gerrit's availability drops, chrome's builds see an excessive
amount of failures, eg:
https://ci.chromium.org/ui/p/chromium/builders/try/linux-rel/1359780/overview
https://ci.chromium.org/ui/p/chromium/builders/try/linux-rel/1359594/overview
https://ci.chromium.org/ui/p/chromium/builders/try/linux-rel/1359564/overview
https://ci.chromium.org/ui/p/chromium/builders/try/linux-rel/1359630/overview

Seemingly all failures occur in either the `gerrit fetch current CL
info` step or the `gerrit changes` step. Both steps have a 60s timeout
and shell out to depot_tools' gerrit_client.py. That script essentially
makes a single http call to gerrit. That request has no configured
timeout. So when gerrit's MIA and the call hangs indefinitely, so too
will the step hang. 60s after that, the step timeout is reached, and the
entire build crashes with an infra-failure.

However, one single retry has been shown to sufficiently work around
at least one instance of that failure:
https://luci-milo.appspot.com/raw/build/logs.chromium.org/chromium/led/bpastene_google.com/dea9a6eca2543e87ee356cedd9d105cdccd375906f690ce10a959701a8fb51ad/+/build.proto

So this incorporates timeouts into the requests made by
gerrit_util.py. Each request is given a 10s timeout, which should be
enough for most/all gerrit calls. (Both steps have a p90 of less than
1sec.) When a timeout is reached, the script will automatically retry
up to 4 times.

This also bumps the timeouts of the step calls to gerrit_client.py to
6min since the script can now take up to 5 minutes to fail, ie:
the sequence of sleeps is roughly 10s, 20s, 40s, 80s, 160s, which is
about 5min. So a 6min timeout should cover all those retries.

This also passes in "--verbose" to all step calls to this script, so
the logging that prints out the retry + sleep log lines will be
visible in build logs.

Recipe-Nontrivial-Roll: build
Recipe-Nontrivial-Roll: build_limited
Recipe-Nontrivial-Roll: chrome_release
Recipe-Nontrivial-Roll: chromiumos
Recipe-Nontrivial-Roll: infra
Bug: 1432638
Change-Id: I9dc47f4beeda3783ae4f9152bd29ee441ac3e197
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/tools/depot_tools/+/4420526
Reviewed-by: Joanna Wang <jojwang@chromium.org>
Commit-Queue: Ben Pastene <bpastene@chromium.org>

gerrit_util.py

@@ -68,6 +68,13 @@ def time_time():
   return time.time()
 
 
+def log_retry_and_sleep(seconds, attempt):
+  LOGGER.info('Will retry in %d seconds (%d more times)...', seconds,
+              TRY_LIMIT - attempt - 1)
+  time_sleep(seconds)
+  return seconds * random.uniform(MIN_BACKOFF, MAX_BACKOFF)
+
+
 class GerritError(Exception):
   """Exception class for errors commuicating with the gerrit-on-borg service."""
   def __init__(self, http_status, message, *args, **kwargs):
@@ -329,10 +336,7 @@ class GceAuthenticator(Authenticator):
       # Retry server error status codes.
       LOGGER.warn('Encountered server error')
       if TRY_LIMIT - i > 1:
-        LOGGER.info('Will retry in %d seconds (%d more times)...',
-                    next_delay_sec, TRY_LIMIT - i - 1)
-        time_sleep(next_delay_sec)
-        next_delay_sec *= random.uniform(MIN_BACKOFF, MAX_BACKOFF)
+        next_delay_sec = log_retry_and_sleep(next_delay_sec, i)
     return None, None
 
   @classmethod
@@ -405,7 +409,7 @@ def CreateHttpConn(host, path, reqtype='GET', headers=None, body=None):
       LOGGER.debug('%s: %s' % (key, val))
     if body:
       LOGGER.debug(body)
-  conn = httplib2.Http()
+  conn = httplib2.Http(timeout=10.0)
   # HACK: httplib2.Http has no such attribute; we store req_host here for later
   # use in ReadHttpResponse.
   conn.req_host = host
@@ -430,7 +434,13 @@ def ReadHttpResponse(conn, accept_statuses=frozenset([200])):
   sleep_time = SLEEP_TIME
   for idx in range(TRY_LIMIT):
     before_response = time.time()
-    response, contents = conn.request(**conn.req_params)
+    try:
+      response, contents = conn.request(**conn.req_params)
+    except socket.timeout:
+      if idx < TRY_LIMIT - 1:
+        sleep_time = log_retry_and_sleep(sleep_time, idx)
+        continue
+      raise
     contents = contents.decode('utf-8', 'replace')
 
     response_time = time.time() - before_response
@@ -468,10 +478,7 @@ def ReadHttpResponse(conn, accept_statuses=frozenset([200])):
                 contents)
 
     if idx < TRY_LIMIT - 1:
-      LOGGER.info('Will retry in %d seconds (%d more times)...',
-                  sleep_time, TRY_LIMIT - idx - 1)
-      time_sleep(sleep_time)
-      sleep_time *= random.uniform(MIN_BACKOFF, MAX_BACKOFF)
+      sleep_time = log_retry_and_sleep(sleep_time, idx)
   # end of retries loop
 
   if response.status in accept_statuses:

recipes/README.recipes.md

@@ -253,7 +253,7 @@ Module for interact with Gerrit endpoints
 
 Wrapper for easy calling of gerrit_utils steps.
 
-— **def [abandon\_change](/recipes/recipe_modules/gerrit/api.py#256)(self, host, change, message=None, name=None, step_test_data=None):**
+— **def [abandon\_change](/recipes/recipe_modules/gerrit/api.py#257)(self, host, change, message=None, name=None, step_test_data=None):**
 
 — **def [call\_raw\_api](/recipes/recipe_modules/gerrit/api.py#31)(self, host, path, method=None, body=None, accept_statuses=None, name=None, \*\*kwargs):**
 
@@ -314,7 +314,7 @@ Gets a branch from given project and commit
 Returns:
   The revision of the branch
 
-— **def [get\_related\_changes](/recipes/recipe_modules/gerrit/api.py#220)(self, host, change, revision='current', step_test_data=None):**
+— **def [get\_related\_changes](/recipes/recipe_modules/gerrit/api.py#221)(self, host, change, revision='current', step_test_data=None):**
 
 Queries related changes for a given host, change, and revision.
 
@@ -346,11 +346,11 @@ Returns:
   A dict for the target revision as documented here:
       https://gerrit-review.googlesource.com/Documentation/rest-api-changes.html#list-changes
 
-— **def [move\_changes](/recipes/recipe_modules/gerrit/api.py#294)(self, host, project, from_branch, to_branch, step_test_data=None):**
+— **def [move\_changes](/recipes/recipe_modules/gerrit/api.py#295)(self, host, project, from_branch, to_branch, step_test_data=None):**
 
-— **def [set\_change\_label](/recipes/recipe_modules/gerrit/api.py#276)(self, host, change, label_name, label_value, name=None, step_test_data=None):**
+— **def [set\_change\_label](/recipes/recipe_modules/gerrit/api.py#277)(self, host, change, label_name, label_value, name=None, step_test_data=None):**
 
-— **def [update\_files](/recipes/recipe_modules/gerrit/api.py#318)(self, host, project, branch, new_contents_by_file_path, commit_msg, params=frozenset(['status=NEW']), cc_list=frozenset([]), submit=False, submit_later=False, step_test_data_create_change=None, step_test_data_submit_change=None):**
+— **def [update\_files](/recipes/recipe_modules/gerrit/api.py#319)(self, host, project, branch, new_contents_by_file_path, commit_msg, params=frozenset(['status=NEW']), cc_list=frozenset([]), submit=False, submit_later=False, step_test_data_create_change=None, step_test_data_submit_change=None):**
 
 Update a set of files by creating and submitting a Gerrit CL.
 

recipes/recipe_modules/bot_update/examples/full.expected/deprecated_got_revision_mapping.json

@@ -4,6 +4,7 @@
       "vpython3",
       "RECIPE_REPO[depot_tools]/gerrit_client.py",
       "changes",
+      "--verbose",
       "--host",
       "https://chromium-review.googlesource.com",
       "--json_file",
@@ -34,7 +35,7 @@
       }
     },
     "name": "gerrit fetch current CL info",
-    "timeout": 60,
+    "timeout": 360,
     "~followup_annotations": [
       "@@@STEP_LOG_LINE@json.output@[@@@",
       "@@@STEP_LOG_LINE@json.output@  {@@@",

recipes/recipe_modules/bot_update/examples/full.expected/tryjob_fail.json

@@ -4,6 +4,7 @@
       "vpython3",
       "RECIPE_REPO[depot_tools]/gerrit_client.py",
       "changes",
+      "--verbose",
       "--host",
       "https://chromium-review.googlesource.com",
       "--json_file",
@@ -34,7 +35,7 @@
       }
     },
     "name": "gerrit fetch current CL info",
-    "timeout": 60,
+    "timeout": 360,
     "~followup_annotations": [
       "@@@STEP_LOG_LINE@json.output@[@@@",
       "@@@STEP_LOG_LINE@json.output@  {@@@",

recipes/recipe_modules/bot_update/examples/full.expected/tryjob_fail_patch.json

@@ -4,6 +4,7 @@
       "vpython3",
       "RECIPE_REPO[depot_tools]/gerrit_client.py",
       "changes",
+      "--verbose",
       "--host",
       "https://chromium-review.googlesource.com",
       "--json_file",
@@ -34,7 +35,7 @@
       }
     },
     "name": "gerrit fetch current CL info",
-    "timeout": 60,
+    "timeout": 360,
     "~followup_annotations": [
       "@@@STEP_LOG_LINE@json.output@[@@@",
       "@@@STEP_LOG_LINE@json.output@  {@@@",

recipes/recipe_modules/bot_update/examples/full.expected/tryjob_fail_patch_download.json

@@ -4,6 +4,7 @@
       "vpython3",
       "RECIPE_REPO[depot_tools]/gerrit_client.py",
       "changes",
+      "--verbose",
       "--host",
       "https://chromium-review.googlesource.com",
       "--json_file",
@@ -34,7 +35,7 @@
       }
     },
     "name": "gerrit fetch current CL info",
-    "timeout": 60,
+    "timeout": 360,
     "~followup_annotations": [
       "@@@STEP_LOG_LINE@json.output@[@@@",
       "@@@STEP_LOG_LINE@json.output@  {@@@",

recipes/recipe_modules/bot_update/examples/full.expected/tryjob_gerrit_angle.json

@@ -4,6 +4,7 @@
       "vpython3",
       "RECIPE_REPO[depot_tools]/gerrit_client.py",
       "changes",
+      "--verbose",
       "--host",
       "https://chromium-review.googlesource.com",
       "--json_file",
@@ -34,7 +35,7 @@
       }
     },
     "name": "gerrit fetch current CL info",
-    "timeout": 60,
+    "timeout": 360,
     "~followup_annotations": [
       "@@@STEP_LOG_LINE@json.output@[@@@",
       "@@@STEP_LOG_LINE@json.output@  {@@@",

recipes/recipe_modules/bot_update/examples/full.expected/tryjob_gerrit_branch_heads.json

@@ -4,6 +4,7 @@
       "vpython3",
       "RECIPE_REPO[depot_tools]/gerrit_client.py",
       "changes",
+      "--verbose",
       "--host",
       "https://chromium-review.googlesource.com",
       "--json_file",
@@ -34,7 +35,7 @@
       }
     },
     "name": "gerrit fetch current CL info",
-    "timeout": 60,
+    "timeout": 360,
     "~followup_annotations": [
       "@@@STEP_LOG_LINE@json.output@[@@@",
       "@@@STEP_LOG_LINE@json.output@  {@@@",

recipes/recipe_modules/bot_update/examples/full.expected/tryjob_gerrit_feature_branch.json

@@ -4,6 +4,7 @@
       "vpython3",
       "RECIPE_REPO[depot_tools]/gerrit_client.py",
       "changes",
+      "--verbose",
       "--host",
       "https://chromium-review.googlesource.com",
       "--json_file",
@@ -34,7 +35,7 @@
       }
     },
     "name": "gerrit fetch current CL info",
-    "timeout": 60,
+    "timeout": 360,
     "~followup_annotations": [
       "@@@STEP_LOG_LINE@json.output@[@@@",
       "@@@STEP_LOG_LINE@json.output@  {@@@",

recipes/recipe_modules/bot_update/examples/full.expected/tryjob_gerrit_v8_feature_branch.json

@@ -4,6 +4,7 @@
       "vpython3",
       "RECIPE_REPO[depot_tools]/gerrit_client.py",
       "changes",
+      "--verbose",
       "--host",
       "https://chromium-review.googlesource.com",
       "--json_file",
@@ -34,7 +35,7 @@
       }
     },
     "name": "gerrit fetch current CL info",
-    "timeout": 60,
+    "timeout": 360,
     "~followup_annotations": [
       "@@@STEP_LOG_LINE@json.output@[@@@",
       "@@@STEP_LOG_LINE@json.output@  {@@@",

recipes/recipe_modules/bot_update/examples/full.expected/tryjob_gerrit_webrtc.json

@@ -4,6 +4,7 @@
       "vpython3",
       "RECIPE_REPO[depot_tools]/gerrit_client.py",
       "changes",
+      "--verbose",
       "--host",
       "https://webrtc-review.googlesource.com",
       "--json_file",
@@ -34,7 +35,7 @@
       }
     },
     "name": "gerrit fetch current CL info",
-    "timeout": 60,
+    "timeout": 360,
     "~followup_annotations": [
       "@@@STEP_LOG_LINE@json.output@[@@@",
       "@@@STEP_LOG_LINE@json.output@  {@@@",

recipes/recipe_modules/bot_update/examples/full.expected/tryjob_v8.json

@@ -4,6 +4,7 @@
       "vpython3",
       "RECIPE_REPO[depot_tools]/gerrit_client.py",
       "changes",
+      "--verbose",
       "--host",
       "https://chromium-review.googlesource.com",
       "--json_file",
@@ -34,7 +35,7 @@
       }
     },
     "name": "gerrit fetch current CL info",
-    "timeout": 60,
+    "timeout": 360,
     "~followup_annotations": [
       "@@@STEP_LOG_LINE@json.output@[@@@",
       "@@@STEP_LOG_LINE@json.output@  {@@@",

recipes/recipe_modules/bot_update/examples/full.expected/tryjob_v8_head_by_default.json

@@ -4,6 +4,7 @@
       "vpython3",
       "RECIPE_REPO[depot_tools]/gerrit_client.py",
       "changes",
+      "--verbose",
       "--host",
       "https://chromium-review.googlesource.com",
       "--json_file",
@@ -34,7 +35,7 @@
       }
     },
     "name": "gerrit fetch current CL info",
-    "timeout": 60,
+    "timeout": 360,
     "~followup_annotations": [
       "@@@STEP_LOG_LINE@json.output@[@@@",
       "@@@STEP_LOG_LINE@json.output@  {@@@",

recipes/recipe_modules/gerrit/api.py

@@ -196,6 +196,7 @@ class GerritApi(recipe_api.RecipeApi):
     """
     args = [
         'changes',
+        '--verbose',
         '--host', host,
         '--json_file', self.m.json.output()
     ]

recipes/recipe_modules/gerrit/examples/full.expected/basic.json

@@ -284,6 +284,7 @@
       "vpython3",
       "RECIPE_REPO[depot_tools]/gerrit_client.py",
       "changes",
+      "--verbose",
       "--host",
       "https://chromium-review.googlesource.com",
       "--json_file",
@@ -320,6 +321,7 @@
       "vpython3",
       "RECIPE_REPO[depot_tools]/gerrit_client.py",
       "changes",
+      "--verbose",
       "--host",
       "https://chromium-review.googlesource.com",
       "--json_file",
@@ -425,6 +427,7 @@
       "vpython3",
       "RECIPE_REPO[depot_tools]/gerrit_client.py",
       "changes",
+      "--verbose",
       "--host",
       "https://chromium-review.googlesource.com",
       "--json_file",
@@ -525,6 +528,7 @@
       "vpython3",
       "RECIPE_REPO[depot_tools]/gerrit_client.py",
       "changes",
+      "--verbose",
       "--host",
       "https://chromium-review.googlesource.com",
       "--json_file",
@@ -551,6 +555,7 @@
       "vpython3",
       "RECIPE_REPO[depot_tools]/gerrit_client.py",
       "changes",
+      "--verbose",
       "--host",
       "https://chromium-review.googlesource.com",
       "--json_file",
@@ -695,6 +700,7 @@
       "vpython3",
       "RECIPE_REPO[depot_tools]/gerrit_client.py",
       "changes",
+      "--verbose",
       "--host",
       "https://chromium-review.googlesource.com",
       "--json_file",

recipes/recipe_modules/tryserver/api.py

@@ -140,7 +140,7 @@ class TryserverApi(recipe_api.RecipeApi):
         o_params=['ALL_REVISIONS', 'DOWNLOAD_COMMANDS'],
         limit=1,
         name='fetch current CL info',
-        timeout=60,
+        timeout=360,
         step_test_data=lambda: self.m.json.test_api.output(mock_res))[0]
 
     self._gerrit_change_target_ref = res['branch']
@@ -348,7 +348,7 @@ class TryserverApi(recipe_api.RecipeApi):
         'https://%s' % self.gerrit_change.host,
         self.gerrit_change_number,
         self.gerrit_patchset_number,
-        timeout=60)
+        timeout=360)
 
   def _get_footers(self, patch_text=None):
     if patch_text is not None:

recipes/recipe_modules/tryserver/examples/full.expected/with_gerrit_patch.json

@@ -4,6 +4,7 @@
       "vpython3",
       "RECIPE_REPO[depot_tools]/gerrit_client.py",
       "changes",
+      "--verbose",
       "--host",
       "https://chromium-review.googlesource.com",
       "--json_file",
@@ -34,7 +35,7 @@
       }
     },
     "name": "gerrit fetch current CL info",
-    "timeout": 60,
+    "timeout": 360,
     "~followup_annotations": [
       "@@@STEP_LOG_LINE@json.output@[@@@",
       "@@@STEP_LOG_LINE@json.output@  {@@@",
@@ -58,6 +59,7 @@
       "vpython3",
       "RECIPE_REPO[depot_tools]/gerrit_client.py",
       "changes",
+      "--verbose",
       "--host",
       "https://chromium-review.googlesource.com",
       "--json_file",
@@ -88,7 +90,7 @@
       }
     },
     "name": "gerrit changes",
-    "timeout": 60,
+    "timeout": 360,
     "~followup_annotations": [
       "@@@STEP_LOG_LINE@json.output@[@@@",
       "@@@STEP_LOG_LINE@json.output@  {@@@",
@@ -146,6 +148,7 @@
       "vpython3",
       "RECIPE_REPO[depot_tools]/gerrit_client.py",
       "changes",
+      "--verbose",
       "--host",
       "https://chromium-review.googlesource.com",
       "--json_file",
@@ -176,7 +179,7 @@
       }
     },
     "name": "gerrit changes (2)",
-    "timeout": 60,
+    "timeout": 360,
     "~followup_annotations": [
       "@@@STEP_LOG_LINE@json.output@[@@@",
       "@@@STEP_LOG_LINE@json.output@  {@@@",
@@ -296,6 +299,7 @@
       "vpython3",
       "RECIPE_REPO[depot_tools]/gerrit_client.py",
       "changes",
+      "--verbose",
       "--host",
       "https://chromium-review.googlesource.com",
       "--json_file",
@@ -326,7 +330,7 @@
       }
     },
     "name": "gerrit fetch current CL info (2)",
-    "timeout": 60,
+    "timeout": 360,
     "~followup_annotations": [
       "@@@STEP_LOG_LINE@json.output@[@@@",
       "@@@STEP_LOG_LINE@json.output@  {@@@",

recipes/recipe_modules/tryserver/examples/full.expected/with_gerrit_patch_and_target_ref.json

@@ -4,6 +4,7 @@
       "vpython3",
       "RECIPE_REPO[depot_tools]/gerrit_client.py",
       "changes",
+      "--verbose",
       "--host",
       "https://chromium-review.googlesource.com",
       "--json_file",
@@ -34,7 +35,7 @@
       }
     },
     "name": "gerrit fetch current CL info",
-    "timeout": 60,
+    "timeout": 360,
     "~followup_annotations": [
       "@@@STEP_LOG_LINE@json.output@[@@@",
       "@@@STEP_LOG_LINE@json.output@  {@@@",
@@ -58,6 +59,7 @@
       "vpython3",
       "RECIPE_REPO[depot_tools]/gerrit_client.py",
       "changes",
+      "--verbose",
       "--host",
       "https://chromium-review.googlesource.com",
       "--json_file",
@@ -88,7 +90,7 @@
       }
     },
     "name": "gerrit changes",
-    "timeout": 60,
+    "timeout": 360,
     "~followup_annotations": [
       "@@@STEP_LOG_LINE@json.output@[@@@",
       "@@@STEP_LOG_LINE@json.output@  {@@@",
@@ -146,6 +148,7 @@
       "vpython3",
       "RECIPE_REPO[depot_tools]/gerrit_client.py",
       "changes",
+      "--verbose",
       "--host",
       "https://chromium-review.googlesource.com",
       "--json_file",
@@ -176,7 +179,7 @@
       }
     },
     "name": "gerrit changes (2)",
-    "timeout": 60,
+    "timeout": 360,
     "~followup_annotations": [
       "@@@STEP_LOG_LINE@json.output@[@@@",
       "@@@STEP_LOG_LINE@json.output@  {@@@",
@@ -296,6 +299,7 @@
       "vpython3",
       "RECIPE_REPO[depot_tools]/gerrit_client.py",
       "changes",
+      "--verbose",
       "--host",
       "https://chromium-review.googlesource.com",
       "--json_file",
@@ -326,7 +330,7 @@
       }
     },
     "name": "gerrit fetch current CL info (2)",
-    "timeout": 60,
+    "timeout": 360,
     "~followup_annotations": [
       "@@@STEP_LOG_LINE@json.output@[@@@",
       "@@@STEP_LOG_LINE@json.output@  {@@@",

recipes/recipe_modules/tryserver/examples/full.expected/with_wrong_patch.json

@@ -4,6 +4,7 @@
       "vpython3",
       "RECIPE_REPO[depot_tools]\\gerrit_client.py",
       "changes",
+      "--verbose",
       "--host",
       "https://chromium-review.googlesource.com",
       "--json_file",
@@ -22,7 +23,7 @@
     },
     "infra_step": true,
     "name": "gerrit fetch current CL info",
-    "timeout": 60,
+    "timeout": 360,
     "~followup_annotations": [
       "@@@STEP_LOG_LINE@json.output@[@@@",
       "@@@STEP_LOG_LINE@json.output@  {@@@",

recipes/recipe_modules/tryserver/examples/full.expected/with_wrong_patch_new.json

@@ -4,6 +4,7 @@
       "vpython3",
       "RECIPE_REPO[depot_tools]\\gerrit_client.py",
       "changes",
+      "--verbose",
       "--host",
       "https://chromium-review.googlesource.com",
       "--json_file",
@@ -22,7 +23,7 @@
     },
     "infra_step": true,
     "name": "gerrit fetch current CL info",
-    "timeout": 60,
+    "timeout": 360,
     "~followup_annotations": [
       "@@@STEP_LOG_LINE@json.output@[@@@",
       "@@@STEP_LOG_LINE@json.output@  {@@@",

tests/gerrit_util_test.py

@@ -12,6 +12,7 @@ import base64
 import httplib2
 import json
 import os
+import socket
 import sys
 import unittest
 
@@ -391,6 +392,17 @@ class GerritUtilTest(unittest.TestCase):
     self.assertEqual(2, len(conn.request.mock_calls))
     gerrit_util.time_sleep.assert_called_once_with(10.0)
 
+  def testReadHttpResponse_TimeoutAndSuccess(self):
+    conn = mock.Mock(req_params={'uri': 'uri', 'method': 'method'})
+    conn.request.side_effect = [
+        socket.timeout('timeout'),
+        (mock.Mock(status=200), b'content\xe2\x9c\x94'),
+    ]
+
+    self.assertEqual('content✔', gerrit_util.ReadHttpResponse(conn).getvalue())
+    self.assertEqual(2, len(conn.request.mock_calls))
+    gerrit_util.time_sleep.assert_called_once_with(10.0)
+
   def testReadHttpResponse_Expected404(self):
     conn = mock.Mock()
     conn.req_params = {'uri': 'uri', 'method': 'method'}