git-cl: Print response headers on 404 Gerrit RPC status.

And ask the user to report the printed headers to the bug.

Bug: 881860
Change-Id: I0a6cc0d90b4a721f72cd7eee4cba59934facbb1e
Reviewed-on: https://chromium-review.googlesource.com/c/1266837
Commit-Queue: Edward Lesmes <ehmaldonado@chromium.org>
Reviewed-by: Andrii Shyshkalov <tandrii@chromium.org>

gerrit_util.py

@@ -44,6 +44,17 @@ TRY_LIMIT = 7
 GERRIT_PROTOCOL = 'https'
 
 
+# TODO(crbug.com/881860): Remove.
+GERRIT_ERR_LOGGER = logging.getLogger('GerritErrorLogs')
+GERRIT_ERR_LOG_FILE = os.path.join(tempfile.gettempdir(), 'GerritHeaders.txt')
+INTERESTING_HEADERS = frozenset([
+    'x-google-backends',
+    'x-google-errorfiltertrace',
+    'x-google-filter-grace',
+    'x-errorid',
+])
+
+
 class GerritError(Exception):
   """Exception class for errors commuicating with the gerrit-on-borg service."""
   def __init__(self, http_status, *args, **kwargs):
@@ -407,6 +418,7 @@ def ReadHttpResponse(conn, accept_statuses=frozenset([200])):
   Returns: A string buffer containing the connection's reply.
   """
   sleep_time = 1.5
+  failed = False
   for idx in range(TRY_LIMIT):
     response, contents = conn.request(**conn.req_params)
 
@@ -433,14 +445,6 @@ def ReadHttpResponse(conn, accept_statuses=frozenset([200])):
       if response.status == 404:
         contents = ''
       break
-    # A status >=500 is assumed to be a possible transient error; retry.
-    http_version = 'HTTP/%s' % ('1.1' if response.version == 11 else '1.0')
-    LOGGER.warn('A transient error occurred while querying %s:\n'
-                '%s %s %s\n'
-                '%s %d %s',
-                conn.req_host, conn.req_params['method'],
-                conn.req_params['uri'],
-                http_version, http_version, response.status, response.reason)
     if response.status == 404:
       # TODO(crbug/881860): remove this hack.
       # HACK: try different Gerrit mirror as a workaround for potentially
@@ -451,12 +455,35 @@ def ReadHttpResponse(conn, accept_statuses=frozenset([200])):
         # And don't increase sleep_time in this case, since we suspect we've
         # just asked wrong git mirror before.
         sleep_time /= 2.0
+        failed = True
+        rpc_headers = '\n'.join(
+            '  ' + header + ': ' + value
+            for header, value in response.iteritems()
+            if header.lower() in INTERESTING_HEADERS
+        )
+        GERRIT_ERR_LOGGER.info('Gerrit RPC failures:\n%s\n', rpc_headers)
+    else:
+      # A status >=500 is assumed to be a possible transient error; retry.
+      http_version = 'HTTP/%s' % ('1.1' if response.version == 11 else '1.0')
+      LOGGER.warn('A transient error occurred while querying %s:\n'
+                  '%s %s %s\n'
+                  '%s %d %s',
+                  conn.req_host, conn.req_params['method'],
+                  conn.req_params['uri'],
+                  http_version, http_version, response.status, response.reason)
 
     if TRY_LIMIT - idx > 1:
       LOGGER.info('Will retry in %d seconds (%d more times)...',
                   sleep_time, TRY_LIMIT - idx - 1)
       time.sleep(sleep_time)
       sleep_time = sleep_time * 2
+  # end of retries loop
+
+  if failed:
+    LOGGER.warn(
+        'If you see this when running \'git cl upload\', consider '
+        'reporting this to https://crbug.com/881860, and please attach the '
+        'failures in %s.\n', GERRIT_ERR_LOG_FILE)
   if response.status not in accept_statuses:
     if response.status in (401, 403):
       print('Your Gerrit credentials might be misconfigured. Try: \n'

git_cl.py

@@ -87,6 +87,10 @@ YAPF_CONFIG_FILENAME = '.style.yapf'
 # Buildbucket master name prefix.
 MASTER_PREFIX = 'master.'
 
+# TODO(crbug.com/881860): Remove
+# Log gerrit failures to a gerrit_util.GERRIT_ERR_LOG_FILE.
+GERRIT_ERR_LOGGER = logging.getLogger('GerritErrorLogs')
+
 # Shortcut since it quickly becomes redundant.
 Fore = colorama.Fore
 
@@ -3165,12 +3169,58 @@ class _GerritChangelistImpl(_ChangelistCodereviewBase):
     refspec = '%s:refs/for/%s%s' % (ref_to_push, branch, refspec_suffix)
 
     try:
+      # TODO(crbug.com/881860): Remove.
+      # Get interesting headers from git push, to be displayed to the user if
+      # subsequent Gerrit RPC calls fail.
+      env = os.environ.copy()
+      env['GIT_CURL_VERBOSE'] = '1'
+      class FilterHeaders(object):
+        """Filter git push headers and store them in a file.
+
+        Regular git push output is printed directly.
+        """
+
+        def __init__(self):
+          # The output from git push that we want to store in a file.
+          self._output = ''
+          # Keeps track of whether the current line is part of a request header.
+          self._on_header = False
+          # Keeps track of repeated empty lines, which mark the end of a request
+          # header.
+          self._last_line_empty = False
+
+        def __call__(self, line):
+          """Handle a single line of git push output."""
+          if not line:
+            # Two consecutive empty lines mark the end of a header.
+            if self._last_line_empty:
+              self._on_header = False
+            self._last_line_empty = True
+            return
+
+          self._last_line_empty = False
+          # A line starting with '>' marks the beggining of a request header.
+          if line[0] == '>':
+            self._on_header = True
+            GERRIT_ERR_LOGGER.info(line)
+          # Lines not starting with '*' or '<', and not part of a request header
+          # should be displayed to the user.
+          elif line[0] not in '*<' and not self._on_header:
+            print(line)
+            # Flush after every line: useful for seeing progress when running as
+            # recipe.
+            sys.stdout.flush()
+          # Filter out the cookie and authorization headers.
+          elif ('cookie: ' not in line.lower()
+                and 'authorization: ' not in line.lower()):
+            GERRIT_ERR_LOGGER.info(line)
+
+      filter_fn = FilterHeaders()
       push_stdout = gclient_utils.CheckCallAndFilter(
           ['git', 'push', self.GetRemoteUrl(), refspec],
-          print_stdout=True,
-          # Flush after every line: useful for seeing progress when running as
-          # recipe.
-          filter_fn=lambda _: sys.stdout.flush())
+          print_stdout=False,
+          filter_fn=filter_fn,
+          env=env)
     except subprocess2.CalledProcessError:
       DieWithError('Failed to create a change. Please examine output above '
                    'for the reason of the failure.\n'
@@ -6207,6 +6257,17 @@ class OptionParser(optparse.OptionParser):
         level=levels[min(options.verbose, len(levels) - 1)],
         format='[%(levelname).1s%(asctime)s %(process)d %(thread)d '
                '%(filename)s] %(message)s')
+
+    # TODO(crbug.com/881860): Remove.
+    # Clear the log after each git-cl run by setting mode='w'.
+    handler = logging.FileHandler(gerrit_util.GERRIT_ERR_LOG_FILE, mode='w')
+    handler.setFormatter(logging.Formatter('%(asctime)s %(message)s'))
+
+    GERRIT_ERR_LOGGER.addHandler(handler)
+    GERRIT_ERR_LOGGER.setLevel(logging.INFO)
+    # Don't propagate to root logger, so that logs are not printed.
+    GERRIT_ERR_LOGGER.propagate = 0
+
     return options, args