Log more info on gerrit 403 errors

If Gerrit returns a 403 on submit, log the text we get in reply to
help diagnose the problem.

Change-Id: I8c9b286bb63ba1703a6a8f3cd6cd9a4b86e62cf2

tests/base.py

@@ -1031,6 +1031,11 @@ class GerritWebServer(object):
                 self.send_response(500)
                 self.end_headers()
 
+            def _403(self, msg):
+                self.send_response(403)
+                self.end_headers()
+                self.wfile.write(msg.encode('utf8'))
+
             def _404(self):
                 self.send_response(404)
                 self.end_headers()
@@ -1073,6 +1078,9 @@ class GerritWebServer(object):
                 if not change:
                     return self._404()
 
+                if not fake_gerrit._fake_submit_permission:
+                    return self._403('submit not permitted')
+
                 candidate = self._get_change(change_id)
                 sr = candidate.getSubmitRecords()
                 if sr[0]['status'] != 'OK':
@@ -1306,6 +1314,8 @@ class FakeGerritConnection(gerritconnection.GerritConnection):
         self._poller_event = poller_event
         self._ref_watcher_event = ref_watcher_event
         self._fake_submit_whole_topic = False
+        self._fake_submit_permission = True
+        self.submit_retry_backoff = 0
 
     def onStop(self):
         super().onStop()

tests/unit/test_gerrit.py

@@ -359,6 +359,25 @@ class TestGerritWeb(ZuulTestCase):
                  changes="1,1 2,1 3,1"),
         ], ordered=False)
 
+    def test_submit_failure(self):
+        # Test that we log the reason for a submit failure (403 error)
+        self.fake_gerrit._fake_submit_permission = False
+        A = self.fake_gerrit.addFakeChange('org/project1', "master", "A")
+        A.addApproval('Code-Review', 2)
+        with self.assertLogs('zuul.test.FakeGerritConnection', level='INFO'
+                             ) as full_logs:
+            self.fake_gerrit.addEvent(A.addApproval('Approved', 1))
+            self.waitUntilSettled()
+            self.log.debug("Full logs:")
+            for x in full_logs.output:
+                self.log.debug(x)
+            self.assertRegexInList(
+                r'Error submitting data to gerrit on attempt 3: '
+                'Received response 403: submit not permitted',
+                full_logs.output)
+
+        self.assertEqual(A.data['status'], 'NEW')
+
 
 class TestFileComments(AnsibleZuulTestCase):
     config_file = 'zuul-gerrit-web.conf'

zuul/driver/gerrit/gerritconnection.py

@@ -589,6 +589,7 @@ class GerritConnection(ZKChangeCacheMixin, ZKBranchCacheMixin, BaseConnection):
     _poller_class = GerritPoller
     _ref_watcher_class = GitWatcher
     ref_watcher_poll_interval = 60
+    submit_retry_backoff = 10
 
     def __init__(self, driver, connection_name, connection_config):
         super(GerritConnection, self).__init__(driver, connection_name,
@@ -753,7 +754,8 @@ class GerritConnection(ZKChangeCacheMixin, ZKBranchCacheMixin, BaseConnection):
         if r.status_code == 400:
             raise HTTPBadRequestException('Received response 400: %s' % r.text)
         elif r.status_code != 200:
-            raise Exception("Received response %s" % (r.status_code,))
+            raise Exception("Received response %s: %s" % (
+                r.status_code, r.text))
         ret = None
         if r.text and len(r.text) > 4:
             try:
@@ -1315,10 +1317,10 @@ class GerritConnection(ZKChangeCacheMixin, ZKBranchCacheMixin, BaseConnection):
                     log.exception(
                         "Bad request submitting check data to gerrit.")
                     break
-                except Exception:
-                    log.exception("Error submitting check data to gerrit, "
-                                  "attempt %s", x)
-                    time.sleep(x * 10)
+                except Exception as e:
+                    log.exception("Error submitting check data to gerrit on "
+                                  "attempt %s: %s", x, e)
+                    time.sleep(x * self.submit_retry_backoff)
 
     def review_http(self, item, message, submit, labels,
                     checks_api, file_comments, phase1, phase2,
@@ -1375,10 +1377,12 @@ class GerritConnection(ZKChangeCacheMixin, ZKBranchCacheMixin, BaseConnection):
                         log.exception(
                             "Bad request submitting check data to gerrit.")
                         break
-                    except Exception:
+                    except Exception as e:
                         log.exception(
-                            "Error submitting data to gerrit, attempt %s", x)
-                        time.sleep(x * 10)
+                            "Error submitting data to gerrit "
+                            "on attempt %s: %s",
+                            x, e)
+                        time.sleep(x * self.submit_retry_backoff)
         if phase2 and change.is_current_patchset and submit:
             for x in range(1, 4):
                 try:
@@ -1392,10 +1396,11 @@ class GerritConnection(ZKChangeCacheMixin, ZKBranchCacheMixin, BaseConnection):
                     log.exception(
                         "Bad request submitting check data to gerrit.")
                     break
-                except Exception:
+                except Exception as e:
                     log.exception(
-                        "Error submitting data to gerrit, attempt %s", x)
-                    time.sleep(x * 10)
+                        "Error submitting data to gerrit on attempt %s: %s",
+                        x, e)
+                    time.sleep(x * self.submit_retry_backoff)
 
     def queryChangeSSH(self, number, event=None):
         args = '--all-approvals --comments --commit-message'