Merge "Update config cache only after all cat jobs complete" into feature/zuulv3
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/zuul/ansible/logconfig.py b/zuul/ansible/logconfig.py
index 86bcd47..b37912d 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'],
@@ -106,10 +106,7 @@
             'level': 'WARN',
         },
     },
-    'root': {
-        'handlers': ['console'],
-        'level': 'WARN',
-    },
+    'root': {'handlers': []},
 }
 
 _DEFAULT_SERVER_FILE_HANDLERS = {
@@ -208,17 +205,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/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/driver/github/githubconnection.py b/zuul/driver/github/githubconnection.py
index bac66f1..6a91ee8 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,28 @@
         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
+        # TODO(mordred) Does it work for Github Apps to get repository
+        # branches? If not, can we avoid doing this as an API for projects that
+        # aren't trying to exclude protected branches by doing a git command
+        # (gerrit driver does an upload pack over ssh)
+        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 +768,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 +785,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)
@@ -846,6 +866,7 @@
         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 +895,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 +911,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 +920,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 +938,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 +948,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 +957,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 +965,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 +1017,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:
+        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():