Merge "Add support for debug statements" into feature/zuulv3
diff --git a/.zuul.yaml b/.zuul.yaml
index 0d21c14..5ebe2a7 100644
--- a/.zuul.yaml
+++ b/.zuul.yaml
@@ -33,4 +33,7 @@
         - tox-py35
     post:
       jobs:
+        - publish-openstack-python-docs:
+            vars:
+              afs_target: 'infra/zuul'
         - publish-openstack-python-branch-tarball
diff --git a/etc/status/public_html/jquery.zuul.js b/etc/status/public_html/jquery.zuul.js
index 1937cd5..c2cf279 100644
--- a/etc/status/public_html/jquery.zuul.js
+++ b/etc/status/public_html/jquery.zuul.js
@@ -554,11 +554,14 @@
                         }
 
                         $.each(changes, function (change_i, change) {
-                            var $change_box =
-                                format.change_with_status_tree(
-                                    change, change_queue);
-                            $html.append($change_box);
-                            format.display_patchset($change_box);
+                            // Only add a change when it has jobs
+                            if (change.jobs.length > 0) {
+                                var $change_box =
+                                    format.change_with_status_tree(
+                                        change, change_queue);
+                                $html.append($change_box);
+                                format.display_patchset($change_box);
+                            }
                         });
                     });
                 });
diff --git a/requirements.txt b/requirements.txt
index 69509d0..eadb508 100644
--- a/requirements.txt
+++ b/requirements.txt
@@ -16,7 +16,7 @@
 apscheduler>=3.0
 PrettyTable>=0.6,<0.8
 babel>=1.0
-ansible>=2.3.0.0
+ansible>=2.3.0.0,<2.4
 kazoo
 sqlalchemy
 alembic
diff --git a/tests/base.py b/tests/base.py
index 357dd7a..c49e1ce 100755
--- a/tests/base.py
+++ b/tests/base.py
@@ -967,6 +967,7 @@
         data = {
             'state': state,
             'sha': self.head_sha,
+            'name': self.project,
             'description': 'Test results for %s: %s' % (self.head_sha, state),
             'target_url': 'http://zuul/%s' % self.head_sha,
             'branches': [],
@@ -1088,8 +1089,9 @@
         }
         return data
 
-    def getPullBySha(self, sha):
-        prs = list(set([p for p in self.pull_requests if sha == p.head_sha]))
+    def getPullBySha(self, sha, project):
+        prs = list(set([p for p in self.pull_requests if
+                        sha == p.head_sha and project == p.project]))
         if len(prs) > 1:
             raise Exception('Multiple pulls found with head sha: %s' % sha)
         pr = prs[0]
diff --git a/tests/fixtures/config/ansible/git/org_plugin-project/playbooks/block_local_override.yaml b/tests/fixtures/config/ansible/git/org_plugin-project/playbooks/block_local_override.yaml
new file mode 100644
index 0000000..58613ad
--- /dev/null
+++ b/tests/fixtures/config/ansible/git/org_plugin-project/playbooks/block_local_override.yaml
@@ -0,0 +1,3 @@
+- hosts: localhost
+  roles:
+    - test-local-override
diff --git a/tests/fixtures/config/ansible/git/org_plugin-project/playbooks/file_local_bad.yaml b/tests/fixtures/config/ansible/git/org_plugin-project/playbooks/file_local_bad.yaml
new file mode 100644
index 0000000..b567dfe
--- /dev/null
+++ b/tests/fixtures/config/ansible/git/org_plugin-project/playbooks/file_local_bad.yaml
@@ -0,0 +1,6 @@
+- hosts: localhost
+  tasks:
+    - name: Try to verify a file in a bad location
+      file:
+        dest: /tmp/unreadable
+        state: absent
diff --git a/tests/fixtures/config/ansible/git/org_plugin-project/playbooks/file_local_good.yaml b/tests/fixtures/config/ansible/git/org_plugin-project/playbooks/file_local_good.yaml
new file mode 100644
index 0000000..29b5431
--- /dev/null
+++ b/tests/fixtures/config/ansible/git/org_plugin-project/playbooks/file_local_good.yaml
@@ -0,0 +1,6 @@
+- hosts: localhost
+  tasks:
+    - name: Try to verify a file in an ok location
+      file:
+        dest: non-existent
+        state: absent
diff --git a/tests/fixtures/config/ansible/git/org_plugin-project/playbooks/roles/test-local-override/library/file.py b/tests/fixtures/config/ansible/git/org_plugin-project/playbooks/roles/test-local-override/library/file.py
new file mode 100644
index 0000000..63478f7
--- /dev/null
+++ b/tests/fixtures/config/ansible/git/org_plugin-project/playbooks/roles/test-local-override/library/file.py
@@ -0,0 +1,31 @@
+# Copyright (c) 2017 Red Hat
+#
+# This module is free software: you can redistribute it and/or modify
+# it under the terms of the GNU General Public License as published by
+# the Free Software Foundation, either version 3 of the License, or
+# (at your option) any later version.
+#
+# This software is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+# GNU General Public License for more details.
+#
+# You should have received a copy of the GNU General Public License
+# along with this software.  If not, see <http://www.gnu.org/licenses/>.
+
+# This file, by existing, should be found instead of ansible's built in
+# file module.
+
+
+def main():
+    module = AnsibleModule(
+        argument_spec=dict(
+            path=dict(required=False, type='str'),
+            state=dict(required=False, type='dict'),
+        )
+    )
+
+    module.exit_json(changed=False)
+
+from ansible.module_utils.basic import *  # noqa
+from ansible.module_utils.basic import AnsibleModule
diff --git a/tests/fixtures/config/ansible/git/org_plugin-project/playbooks/roles/test-local-override/tasks/main.yaml b/tests/fixtures/config/ansible/git/org_plugin-project/playbooks/roles/test-local-override/tasks/main.yaml
new file mode 100644
index 0000000..a06608b
--- /dev/null
+++ b/tests/fixtures/config/ansible/git/org_plugin-project/playbooks/roles/test-local-override/tasks/main.yaml
@@ -0,0 +1,4 @@
+- name: Attempt to use local version of file.py
+  file:
+    path: some-file.out
+    state: touch
diff --git a/tests/unit/test_v3.py b/tests/unit/test_v3.py
index 60a0986..9d695aa 100755
--- a/tests/unit/test_v3.py
+++ b/tests/unit/test_v3.py
@@ -886,6 +886,9 @@
             ('csvfile_bad', 'FAILURE'),
             ('uri_bad_path', 'FAILURE'),
             ('uri_bad_scheme', 'FAILURE'),
+            ('block_local_override', 'FAILURE'),
+            ('file_local_good', 'SUCCESS'),
+            ('file_local_bad', 'FAILURE'),
         ]
         for job_name, result in plugin_tests:
             count += 1
diff --git a/zuul/ansible/action/assemble.py b/zuul/ansible/action/assemble.py
index 2cc7eb7..30920e2 100644
--- a/zuul/ansible/action/assemble.py
+++ b/zuul/ansible/action/assemble.py
@@ -22,6 +22,9 @@
 
     def run(self, tmp=None, task_vars=None):
 
+        if not paths._is_official_module(self):
+            return paths._fail_module_dict(self._task.action)
+
         source = self._task.args.get('src', None)
         remote_src = self._task.args.get('remote_src', False)
 
diff --git a/zuul/ansible/action/copy.py b/zuul/ansible/action/copy.py
index d870c24..f00164d 100644
--- a/zuul/ansible/action/copy.py
+++ b/zuul/ansible/action/copy.py
@@ -22,6 +22,9 @@
 
     def run(self, tmp=None, task_vars=None):
 
+        if not paths._is_official_module(self):
+            return paths._fail_module_dict(self._task.action)
+
         source = self._task.args.get('src', None)
         remote_src = self._task.args.get('remote_src', False)
 
diff --git a/zuul/ansible/action/fetch.py b/zuul/ansible/action/fetch.py
index 170b655..0d35846 100644
--- a/zuul/ansible/action/fetch.py
+++ b/zuul/ansible/action/fetch.py
@@ -21,6 +21,8 @@
 class ActionModule(fetch.ActionModule):
 
     def run(self, tmp=None, task_vars=None):
+        if not paths._is_official_module(self):
+            return paths._fail_module_dict(self._task.action)
 
         dest = self._task.args.get('dest', None)
 
diff --git a/zuul/ansible/action/include_vars.py b/zuul/ansible/action/include_vars.py
index 5bc1d76..739c8a4 100644
--- a/zuul/ansible/action/include_vars.py
+++ b/zuul/ansible/action/include_vars.py
@@ -21,6 +21,8 @@
 class ActionModule(include_vars.ActionModule):
 
     def run(self, tmp=None, task_vars=None):
+        if not paths._is_official_module(self):
+            return paths._fail_module_dict(self._task.action)
 
         source_dir = self._task.args.get('dir', None)
         source_file = self._task.args.get('file', None)
diff --git a/zuul/ansible/action/normal.py b/zuul/ansible/action/normal.py
index 803b0a7..34df21d 100644
--- a/zuul/ansible/action/normal.py
+++ b/zuul/ansible/action/normal.py
@@ -50,6 +50,7 @@
         handler_name = 'handle_{action}'.format(action=self._task.action)
         handler = getattr(self, handler_name, None)
         if handler:
+            paths._fail_if_local_module(self)
             handler()
             return True
         return False
diff --git a/zuul/ansible/action/patch.py b/zuul/ansible/action/patch.py
index 0b43c82..cac6f2f 100644
--- a/zuul/ansible/action/patch.py
+++ b/zuul/ansible/action/patch.py
@@ -21,6 +21,8 @@
 class ActionModule(patch.ActionModule):
 
     def run(self, tmp=None, task_vars=None):
+        if not paths._is_official_module(self):
+            return paths._fail_module_dict(self._task.action)
 
         source = self._task.args.get('src', None)
         remote_src = self._task.args.get('remote_src', False)
diff --git a/zuul/ansible/action/script.py b/zuul/ansible/action/script.py
index c95d357..f67a73e 100644
--- a/zuul/ansible/action/script.py
+++ b/zuul/ansible/action/script.py
@@ -22,6 +22,8 @@
 
     def run(self, tmp=None, task_vars=None):
 
+        if not paths._is_official_module(self):
+            return paths._fail_module_dict(self._task.action)
         # the script name is the first item in the raw params, so we split it
         # out now so we know the file name we need to transfer to the remote,
         # and everything else is an argument to the script which we need later
diff --git a/zuul/ansible/action/synchronize.py b/zuul/ansible/action/synchronize.py
index 75fd45f..6e778d1 100644
--- a/zuul/ansible/action/synchronize.py
+++ b/zuul/ansible/action/synchronize.py
@@ -21,6 +21,8 @@
 class ActionModule(synchronize.ActionModule):
 
     def run(self, tmp=None, task_vars=None):
+        if not paths._is_official_module(self):
+            return paths._fail_module_dict(self._task.action)
 
         source = self._task.args.get('src', None)
         dest = self._task.args.get('dest', None)
diff --git a/zuul/ansible/action/template.py b/zuul/ansible/action/template.py
index c6df3d8..f2fbd36 100644
--- a/zuul/ansible/action/template.py
+++ b/zuul/ansible/action/template.py
@@ -21,6 +21,8 @@
 class ActionModule(template.ActionModule):
 
     def run(self, tmp=None, task_vars=None):
+        if not paths._is_official_module(self):
+            return paths._fail_module_dict(self._task.action)
 
         source = self._task.args.get('src', None)
 
diff --git a/zuul/ansible/action/unarchive.py b/zuul/ansible/action/unarchive.py
index c78c331..5eb3d9f 100644
--- a/zuul/ansible/action/unarchive.py
+++ b/zuul/ansible/action/unarchive.py
@@ -21,6 +21,8 @@
 class ActionModule(unarchive.ActionModule):
 
     def run(self, tmp=None, task_vars=None):
+        if not paths._is_official_module(self):
+            return paths._fail_module_dict(self._task.action)
 
         source = self._task.args.get('src', None)
         remote_src = self._task.args.get('remote_src', False)
diff --git a/zuul/ansible/action/win_copy.py b/zuul/ansible/action/win_copy.py
index 2751585..8fb95be 100644
--- a/zuul/ansible/action/win_copy.py
+++ b/zuul/ansible/action/win_copy.py
@@ -21,6 +21,8 @@
 class ActionModule(win_copy.ActionModule):
 
     def run(self, tmp=None, task_vars=None):
+        if not paths._is_official_module(self):
+            return paths._fail_module_dict(self._task.action)
 
         source = self._task.args.get('src', None)
         remote_src = self._task.args.get('remote_src', False)
diff --git a/zuul/ansible/action/win_template.py b/zuul/ansible/action/win_template.py
index 7a357f9..1b6a890 100644
--- a/zuul/ansible/action/win_template.py
+++ b/zuul/ansible/action/win_template.py
@@ -21,6 +21,8 @@
 class ActionModule(win_template.ActionModule):
 
     def run(self, tmp=None, task_vars=None):
+        if not paths._is_official_module(self):
+            return paths._fail_module_dict(self._task.action)
 
         source = self._task.args.get('src', None)
         remote_src = self._task.args.get('remote_src', False)
diff --git a/zuul/ansible/logconfig.py b/zuul/ansible/logconfig.py
index 86bcd47..7c3507b 100644
--- a/zuul/ansible/logconfig.py
+++ b/zuul/ansible/logconfig.py
@@ -80,14 +80,14 @@
             # Used for printing to stdout
             'class': 'logging.StreamHandler',
             'stream': 'ext://sys.stdout',
-            'level': 'WARNING',
+            'level': 'INFO',
             'formatter': 'simple',
         },
     },
     'loggers': {
         'zuul': {
             'handlers': ['console'],
-            'level': 'DEBUG',
+            'level': 'INFO',
         },
         'sqlalchemy.engine': {
             'handlers': ['console'],
@@ -105,11 +105,12 @@
             'handlers': ['console'],
             'level': 'WARN',
         },
+        'cachecontrol': {
+            'handlers': ['console'],
+            'level': 'INFO',
+        },
     },
-    'root': {
-        'handlers': ['console'],
-        'level': 'WARN',
-    },
+    'root': {'handlers': []},
 }
 
 _DEFAULT_SERVER_FILE_HANDLERS = {
@@ -208,17 +209,20 @@
             server_handler = handler.copy()
             server_handler['filename'] = server_handler['filename'].format(
                 server=server)
-            self._config['handlers'][name] = handler
+            self._config['handlers'][name] = server_handler
         # Change everything configured to write to stdout to write to
-        # log files instead. This leaves root going to console, which is
-        # how the loggers infra uses work.
-        # NOTE(mordred) root -> console may not actually be intentional. It can
-        #               be changed by changing
-        #               _DEFAULT_SERVER_LOGGING_CONFIG['root']['handlers']
+        # log files instead.
         for logger in self._config['loggers'].values():
             if logger['handlers'] == ['console']:
                 logger['handlers'] = ['normal']
 
+    def setDebug(self):
+        # Change level from INFO to DEBUG
+        for section in ('handlers', 'loggers'):
+            for handler in self._config[section].values():
+                if handler.get('level') == 'INFO':
+                    handler['level'] = 'DEBUG'
+
 
 class FileLoggingConfig(LoggingConfig):
 
diff --git a/zuul/ansible/paths.py b/zuul/ansible/paths.py
index bc61975..04daef4 100644
--- a/zuul/ansible/paths.py
+++ b/zuul/ansible/paths.py
@@ -17,6 +17,7 @@
 import os
 
 from ansible.errors import AnsibleError
+import ansible.modules
 import ansible.plugins.action
 import ansible.plugins.lookup
 
@@ -67,3 +68,30 @@
     return imp.load_module(
         'zuul.ansible.protected.lookup.' + name,
         *imp.find_module(name, ansible.plugins.lookup.__path__))
+
+
+def _is_official_module(module):
+    task_module_path = module._shared_loader_obj.module_loader.find_plugin(
+        module._task.action)
+    ansible_module_path = os.path.dirname(ansible.modules.__file__)
+
+    # If the module is not beneath the main ansible library path that means
+    # someone has included a module with a playbook or a role that has the
+    # same name as one of the builtin modules. Normally we don't care, but for
+    # local execution it's a problem because their version could subvert our
+    # path checks and/or do other things on the local machine that we don't
+    # want them to do.
+    return task_module_path.startswith(ansible_module_path)
+
+
+def _fail_module_dict(module_name):
+    return dict(
+        failed=True,
+        msg="Local execution of overridden module {name} is forbidden".format(
+            name=module_name))
+
+
+def _fail_if_local_module(module):
+    if not _is_official_module(module):
+        msg_dict = _fail_module_dict(module._task.action)
+        raise AnsibleError(msg_dict['msg'])
diff --git a/zuul/cmd/__init__.py b/zuul/cmd/__init__.py
index f677b5e..a5db9a6 100755
--- a/zuul/cmd/__init__.py
+++ b/zuul/cmd/__init__.py
@@ -84,12 +84,13 @@
     def setup_logging(self, section, parameter):
         if self.config.has_option(section, parameter):
             fp = os.path.expanduser(self.config.get(section, parameter))
-            logging_config = logconfig.load_config_from_file(fp)
+            logging_config = logconfig.load_config(fp)
         else:
             # If someone runs in the foreground and doesn't give a logging
             # config, leave the config set to emit to stdout.
-            if hasattr(self.args, 'nodaemon') and not self.args.nodaemon:
+            if hasattr(self.args, 'nodaemon') and self.args.nodaemon:
                 logging_config = logconfig.ServerLoggingConfig()
+                logging_config.setDebug()
             else:
                 # Setting a server value updates the defaults to use
                 # WatchedFileHandler on /var/log/zuul/{server}-debug.log
diff --git a/zuul/configloader.py b/zuul/configloader.py
index c925024..94c0d2a 100644
--- a/zuul/configloader.py
+++ b/zuul/configloader.py
@@ -460,6 +460,8 @@
             else:
                 secret_name = secret_config['name']
                 secret = layout.secrets[secret_config['secret']]
+            if secret_name == 'zuul':
+                raise Exception("Secrets named 'zuul' are not allowed.")
             if secret.source_context != job.source_context:
                 raise Exception(
                     "Unable to use secret %s.  Secrets must be "
@@ -574,6 +576,8 @@
 
         variables = conf.get('vars', None)
         if variables:
+            if 'zuul' in variables:
+                raise Exception("Variables named 'zuul' are not allowed.")
             job.updateVariables(variables)
 
         allowed_projects = conf.get('allowed-projects', None)
@@ -648,6 +652,7 @@
     def getSchema(layout):
         project_template = {
             vs.Required('name'): str,
+            'description': str,
             'merge-mode': vs.Any(
                 'merge', 'merge-resolve',
                 'cherry-pick'),
@@ -717,6 +722,7 @@
     def getSchema(layout):
         project = {
             vs.Required('name'): str,
+            'description': str,
             'templates': [str],
             'merge-mode': vs.Any('merge', 'merge-resolve',
                                  'cherry-pick'),
@@ -1228,6 +1234,14 @@
                                  untrusted_projects, cached, tenant):
         config_projects_config = model.UnparsedTenantConfig()
         untrusted_projects_config = model.UnparsedTenantConfig()
+        # project -> config; these will replace
+        # project.unparsed_config if this method succesfully
+        # completes
+        new_project_unparsed_config = {}
+        # project -> branch -> config; these will replace
+        # project.unparsed_branch_config if this method succesfully
+        # completes
+        new_project_unparsed_branch_config = {}
         jobs = []
 
         # In some cases, we can use cached data, but it's still
@@ -1247,7 +1261,7 @@
                 continue
             # Otherwise, prepare an empty unparsed config object to
             # hold cached data later.
-            project.unparsed_config = model.UnparsedTenantConfig()
+            new_project_unparsed_config[project] = model.UnparsedTenantConfig()
             # Get main config files.  These files are permitted the
             # full range of configuration.
             job = merger.getFiles(
@@ -1266,7 +1280,8 @@
                 continue
             # Otherwise, prepare an empty unparsed config object to
             # hold cached data later.
-            project.unparsed_config = model.UnparsedTenantConfig()
+            new_project_unparsed_config[project] = model.UnparsedTenantConfig()
+            new_project_unparsed_branch_config[project] = {}
             # Get in-project-repo config files which have a restricted
             # set of options.
             # For each branch in the repo, get the zuul.yaml for that
@@ -1274,7 +1289,7 @@
             # branch selector to each job there.  This makes the
             # in-repo configuration apply only to that branch.
             for branch in project.source.getProjectBranches(project, tenant):
-                project.unparsed_branch_config[branch] = \
+                new_project_unparsed_branch_config[project][branch] = \
                     model.UnparsedTenantConfig()
                 job = merger.getFiles(
                     project.source.connection.connection_name,
@@ -1333,9 +1348,19 @@
                         incdata = TenantParser._parseUntrustedProjectLayout(
                             job.files[fn], job.source_context)
                         untrusted_projects_config.extend(incdata)
-                    project.unparsed_config.extend(incdata)
-                    if branch in project.unparsed_branch_config:
-                        project.unparsed_branch_config[branch].extend(incdata)
+                    new_project_unparsed_config[project].extend(incdata)
+                    if branch in new_project_unparsed_branch_config.get(
+                            project, {}):
+                        new_project_unparsed_branch_config[project][branch].\
+                            extend(incdata)
+        # Now that we've sucessfully loaded all of the configuration,
+        # cache the unparsed data on the project objects.
+        for project, data in new_project_unparsed_config.items():
+            project.unparsed_config = data
+        for project, branch_config in \
+            new_project_unparsed_branch_config.items():
+            for branch, data in branch_config.items():
+                project.unparsed_branch_config[branch] = data
         return config_projects_config, untrusted_projects_config
 
     @staticmethod
diff --git a/zuul/driver/bubblewrap/__init__.py b/zuul/driver/bubblewrap/__init__.py
index 149874b..7059351 100644
--- a/zuul/driver/bubblewrap/__init__.py
+++ b/zuul/driver/bubblewrap/__init__.py
@@ -212,6 +212,7 @@
         for path in ['/lib64',
                      '/etc/nsswitch.conf',
                      '/etc/lsb-release.d',
+                     '/etc/alternatives',
                      ]:
             if os.path.exists(path):
                 bwrap_command.extend(['--ro-bind', path, path])
diff --git a/zuul/driver/github/githubconnection.py b/zuul/driver/github/githubconnection.py
index bac66f1..0ce6ef5 100644
--- a/zuul/driver/github/githubconnection.py
+++ b/zuul/driver/github/githubconnection.py
@@ -29,7 +29,7 @@
 import webob.dec
 import voluptuous as v
 import github3
-from github3.exceptions import MethodNotAllowed
+import github3.exceptions
 
 from zuul.connection import BaseConnection
 from zuul.model import Ref, Branch, Tag
@@ -252,7 +252,8 @@
         action = body.get('action')
         if action == 'pending':
             return
-        pr_body = self.connection.getPullBySha(body['sha'])
+        project = body.get('name')
+        pr_body = self.connection.getPullBySha(body['sha'], project)
         if pr_body is None:
             return
 
@@ -350,6 +351,7 @@
     def _init_data(self):
         if self._data is None:
             user = self._github.user(self._username)
+            self.log.debug("Initialized data for user %s", self._username)
             log_rate_limit(self.log, self._github)
             self._data = {
                 'username': user.login,
@@ -367,6 +369,7 @@
         super(GithubConnection, self).__init__(
             driver, connection_name, connection_config)
         self._change_cache = {}
+        self._project_branch_cache = {}
         self.projects = {}
         self.git_ssh_key = self.connection_config.get('sshkey')
         self.server = self.connection_config.get('server', 'github.com')
@@ -423,6 +426,9 @@
         # anything going through requests to http/s goes through cache
         github.session.mount('http://', self.cache_adapter)
         github.session.mount('https://', self.cache_adapter)
+        # Add properties to store project and user for logging later
+        github._zuul_project = None
+        github._zuul_user_id = None
         return github
 
     def _authenticateGithubAPI(self):
@@ -509,6 +515,8 @@
         if use_app and project and self.app_id:
             github = self._createGithubClient()
             github.login(token=self._get_installation_key(project, user_id))
+            github._zuul_project = project
+            github._zuul_user_id = user_id
             return github
 
         # if we're using api_key authentication then this is already token
@@ -614,6 +622,7 @@
             prs.append(pr)
             seen.add(issue)
 
+        self.log.debug("Ran search issues: %s", query)
         log_rate_limit(self.log, github)
         return prs
 
@@ -718,13 +727,24 @@
         else:
             exclude_unprotected = tenant.exclude_unprotected_branches
 
-        github = self.getGithubClient()
-        owner, proj = project.name.split('/')
-        repository = github.repository(owner, proj)
-        branches = [branch.name for branch in repository.branches(
-            protected=exclude_unprotected)]
-        log_rate_limit(self.log, github)
-        return branches
+        github = self.getGithubClient(project.name)
+        try:
+            owner, proj = project.name.split('/')
+            repository = github.repository(owner, proj)
+            self._project_branch_cache[project.name] = [
+                branch.name for branch in repository.branches(
+                    protected=exclude_unprotected)]
+            self.log.debug('Got project branches for %s', project.name)
+            log_rate_limit(self.log, github)
+        except github3.exceptions.ForbiddenError as e:
+            self.log.error(str(e), exc_info=True)
+            rate_limit = github.rate_limit()
+            if rate_limit['resources']['core']['remaining'] == 0:
+                self.log.debug("Rate limit exceeded, using stale branch list")
+            else:
+                self.log.error(str(e), exc_info=True)
+
+        return self._project_branch_cache[project.name]
 
     def getPullUrl(self, project, number):
         return '%s/pull/%s' % (self.getGitwebUrl(project), number)
@@ -744,6 +764,7 @@
         pr = probj.as_dict()
         pr['files'] = [f.filename for f in probj.files()]
         pr['labels'] = [l.name for l in issueobj.labels()]
+        self.log.debug('Got PR %s#%s', project_name, number)
         log_rate_limit(self.log, github)
         return pr
 
@@ -760,24 +781,19 @@
         # For now, just send back a True value.
         return True
 
-    def getPullBySha(self, sha):
-        query = '%s type:pr is:open' % sha
+    def getPullBySha(self, sha, project):
         pulls = []
-        github = self.getGithubClient()
-        for issue in github.search_issues(query=query):
-            pr_url = issue.issue.pull_request().as_dict().get('url')
-            if not pr_url:
-                continue
-            # the issue provides no good description of the project :\
-            owner, project, _, number = pr_url.split('/')[-4:]
-            github = self.getGithubClient("%s/%s" % (owner, project))
-            pr = github.pull_request(owner, project, number)
+        owner, project = project.split('/')
+        github = self.getGithubClient("%s/%s" % (owner, project))
+        repo = github.repository(owner, project)
+        for pr in repo.pull_requests(state='open'):
             if pr.head.sha != sha:
                 continue
             if pr.as_dict() in pulls:
                 continue
             pulls.append(pr.as_dict())
 
+        self.log.debug('Got PR on project %s for sha %s', project, sha)
         log_rate_limit(self.log, github)
         if len(pulls) > 1:
             raise Exception('Multiple pulls found with head sha %s' % sha)
@@ -839,13 +855,11 @@
     def _getPullReviews(self, owner, project, number):
         # make a list out of the reviews so that we complete our
         # API transaction
-        # reviews are not yet supported by integrations, use api_key:
-        # https://platform.github.community/t/api-endpoint-for-pr-reviews/409
-        github = self.getGithubClient("%s/%s" % (owner, project),
-                                      use_app=False)
+        github = self.getGithubClient("%s/%s" % (owner, project))
         reviews = [review.as_dict() for review in
                    github.pull_request(owner, project, number).reviews()]
 
+        self.log.debug('Got reviews for PR %s/%s#%s', owner, project, number)
         log_rate_limit(self.log, github)
         return reviews
 
@@ -874,6 +888,7 @@
         # Get the data
         perms = repository._get(url, headers=headers)
 
+        self.log.debug("Got repo permissions for %s/%s", owner, proj)
         log_rate_limit(self.log, github)
 
         # no known user, maybe deleted since review?
@@ -889,6 +904,7 @@
         repository = github.repository(owner, proj)
         pull_request = repository.issue(pr_number)
         pull_request.create_comment(message)
+        self.log.debug("Commented on PR %s/%s#%s", owner, proj, pr_number)
         log_rate_limit(self.log, github)
 
     def mergePull(self, project, pr_number, commit_message='', sha=None):
@@ -897,9 +913,11 @@
         pull_request = github.pull_request(owner, proj, pr_number)
         try:
             result = pull_request.merge(commit_message=commit_message, sha=sha)
-        except MethodNotAllowed as e:
+        except github3.exceptions.MethodNotAllowed as e:
             raise MergeFailure('Merge was not successful due to mergeability'
                                ' conflict, original error is %s' % e)
+
+        self.log.debug("Merged PR %s/%s#%s", owner, proj, pr_number)
         log_rate_limit(self.log, github)
         if not result:
             raise Exception('Pull request was not merged')
@@ -913,6 +931,7 @@
         # API transaction
         statuses = [status.as_dict() for status in commit.statuses()]
 
+        self.log.debug("Got commit statuses for sha %s on %s", sha, project)
         log_rate_limit(self.log, github)
         return statuses
 
@@ -922,6 +941,8 @@
         owner, proj = project.split('/')
         repository = github.repository(owner, proj)
         repository.create_status(sha, state, url, description, context)
+        self.log.debug("Set commit status to %s for sha %s on %s",
+                       state, sha, project)
         log_rate_limit(self.log, github)
 
     def labelPull(self, project, pr_number, label):
@@ -929,6 +950,7 @@
         owner, proj = project.split('/')
         pull_request = github.issue(owner, proj, pr_number)
         pull_request.add_labels(label)
+        self.log.debug("Added label %s to %s#%s", label, proj, pr_number)
         log_rate_limit(self.log, github)
 
     def unlabelPull(self, project, pr_number, label):
@@ -936,6 +958,7 @@
         owner, proj = project.split('/')
         pull_request = github.issue(owner, proj, pr_number)
         pull_request.remove_label(label)
+        self.log.debug("Removed label %s from %s#%s", label, proj, pr_number)
         log_rate_limit(self.log, github)
 
     def getPushedFileNames(self, event):
@@ -987,8 +1010,12 @@
         reset = rate_limit['resources']['core']['reset']
     except:
         return
-    log.debug('GitHub API rate limit remaining: %s reset: %s' %
-              (remaining, reset))
+    if github._zuul_user_id:
+        log.debug('GitHub API rate limit (%s, %s) remaining: %s reset: %s',
+                  github._zuul_project, github._zuul_user_id, remaining, reset)
+    else:
+        log.debug('GitHub API rate limit remaining: %s reset: %s',
+                  remaining, reset)
 
 
 def getSchema():
diff --git a/zuul/executor/server.py b/zuul/executor/server.py
index 96c809c..3daafc7 100644
--- a/zuul/executor/server.py
+++ b/zuul/executor/server.py
@@ -1281,6 +1281,8 @@
         secrets = playbook['secrets']
         if secrets:
             if 'zuul' in secrets:
+                # We block this in configloader, but block it here too to make
+                # sure that a job doesn't pass secrets named zuul.
                 raise Exception("Defining secrets named 'zuul' is not allowed")
             jobdir_playbook.secrets_content = yaml.safe_dump(
                 secrets, default_flow_style=False)
@@ -1385,6 +1387,8 @@
         # TODO(mordred) Hack to work around running things with python3
         all_vars['ansible_python_interpreter'] = '/usr/bin/python2'
         if 'zuul' in all_vars:
+            # We block this in configloader, but block it here too to make
+            # sure that a job doesn't pass variables named zuul.
             raise Exception("Defining vars named 'zuul' is not allowed")
         all_vars['zuul'] = args['zuul'].copy()
         all_vars['zuul']['executor'] = dict(