# Copyright 2017 The Chromium OS Authors. All rights reserved.
# Use of this source code is governed by a BSD-style license that can be
# found in the LICENSE file.

"""Invokes git bisect to find culprit commit."""

from __future__ import print_function

import datetime

from chromite.cros_bisect import common
from chromite.lib import cros_build_lib
from chromite.lib import cros_logging as logging
from chromite.lib import git


class GitBisector(common.OptionsChecker):
  """Bisects suspicious commits in a git repository.

  Before bisect, it does sanity check for the given good and bad commit. Then
  it extracts metric scores for both commits as baseline to determine the
  upcoming bisect candidate's status.

  It finds first bad commit within given good and bad commit using "git bisect"
  command. For each commit, it uses builder to build package to verify and
  deploy it to DUT (device under test). And asks evaluator to extract score
  of the commit. It is treated as good commit i the score is closer to user
  specified good commit.

  Finally, it outputs git bisect result.
  """

  REQUIRED_ARGS = ('good', 'bad', 'remote', 'eval_repeat')

  def __init__(self, options, builder, evaluator):
    """Constructor.

    Args:
      options: An argparse.Namespace to hold command line arguments. Should
        contain:
        * good: Last known good commit.
        * bad: Last known bad commit.
        * remote: DUT (refer lib.commandline.Device).
        * eval_repeat: Run test for N times. None means 1.
      builder: Builder to build/deploy image. Should contain repo_dir.
      evaluator: Evaluator to get score
    """
    super(GitBisector, self).__init__(options)
    self.good_commit = options.good
    self.bad_commit = options.bad
    self.remote = options.remote
    self.eval_repeat = options.eval_repeat
    self.builder = builder
    self.evaluator = evaluator
    self.repo_dir = self.builder.repo_dir

    # Initialized in SanityCheck().
    self.good_score = None
    self.bad_score = None

    # If the distance between current commit's score and given good commit is
    # shorter than threshold, treat the commit as good one. The threshold is set
    # by user.
    self.threshold = None

    # Update in UpdateCurrentCommit().
    self.current_commit = common.CommitInfo()

  def SetUp(self):
    """Sets up environment to bisect."""
    logging.info('Set up builder environment.')
    self.builder.SetUp()

  def Git(self, command):
    """Wrapper of git.RunGit.

    It passes self.repo_dir as git_repo to git.RunGit.

    Args:
      command: git command.

    Returns:
      A CommandResult object.
    """
    return git.RunGit(self.repo_dir, command)

  def UpdateCurrentCommit(self):
    """Updates self.current_commit."""
    result = self.Git(['show', '--no-patch', '--format=%h %ct %s'])
    if result.returncode != 0:
      logging.error('Failed to update current commit info.')
      return

    fields = result.output.strip().split()
    if len(fields) < 3:
      logging.error('Failed to update current commit info.')
      return
    sha1 = fields[0]
    timestamp = int(fields[1])
    title = ' '.join(fields[2:])
    self.current_commit = common.CommitInfo(sha1=sha1, title=title,
                                            timestamp=timestamp)

  def GetCommitTimestamp(self, sha1):
    """Obtains given commit's timestamp.

    Args:
      sha1: Commit's SHA1 to look up.

    Returns:
      timestamp in integer. None if the commit does not exist.
    """
    result = self.Git(['show', '--no-patch', '--format=%ct', sha1])
    if result.returncode == 0:
      try:
        return int(result.output.strip())
      except ValueError:
        pass
    return None

  def SanityCheck(self):
    """Evaluates last known good and bad commit again.

    To make sure that good commit has better evaluation score on the DUT, it
    builds, deploys and evaluates both good and bad images on the DUT.

    Returns:
      (good_commit_info, bad_commit_info)
    """
    logging.info('Perform sanity check on good commit %s and bad commit %s',
                 self.good_commit, self.bad_commit)
    # Builder is lazy syncing to HEAD. Sync to HEAD if good_commit or bad_commit
    # does not exist in repo.
    if (not git.DoesCommitExistInRepo(self.repo_dir, self.good_commit) or
        not git.DoesCommitExistInRepo(self.repo_dir, self.bad_commit)):
      logging.info(
          'Either good commit (%s) or bad commit (%s) not found in repo. '
          'Try syncing to HEAD first.', self.good_commit, self.bad_commit)
      self.builder.SyncToHead()
    else:
      logging.info(
          'Both good commit (%s) and bad commit (%s) are found in repo. '
          'No need to update repo.', self.good_commit, self.bad_commit)

    good_commit_timestamp = self.GetCommitTimestamp(self.good_commit)
    if good_commit_timestamp is None:
      logging.error('Sanity check failed: good commit %s does not exist.',
                    self.good_commit)
      return None, None
    bad_commit_timestamp = self.GetCommitTimestamp(self.bad_commit)
    if bad_commit_timestamp is None:
      logging.error('Sanity check failed: bad commit %s does not exist.',
                    self.bad_commit)
      return None, None

    # TODO(deanliao): Consider the case that we want to find a commit that
    #     fixed a problem.
    if bad_commit_timestamp < good_commit_timestamp:
      logging.error(
          'Sanity check failed: good commit (%s) timestamp: %s should be '
          'earlier than bad commit (%s): %s',
          self.good_commit, good_commit_timestamp,
          self.bad_commit, bad_commit_timestamp)
      return None, None

    logging.notice('Obtaining score of good commit %s', self.good_commit)
    self.Git(['checkout', self.good_commit])
    self.good_score = self.BuildDeployEval()
    good_commit_info = self.current_commit
    good_commit_info.label = 'last-known-good  '

    logging.notice('Obtaining score of bad commit %s', self.bad_commit)
    self.Git(['checkout', self.bad_commit])
    self.bad_score = self.BuildDeployEval()
    bad_commit_info = self.current_commit
    bad_commit_info.label = 'last-known-bad   '
    return (good_commit_info, bad_commit_info)

  def GetThresholdFromUser(self):
    """Gets threshold that decides good/bad commit.

    It gives user the measured last known good and bad score's statistics to
    help user determine a reasonable threshold.
    """
    logging.notice('Good commit score mean: %.3f  STD: %.3f\n'
                   'Bad commit score mean: %.3f  STD: %.3f',
                   self.good_score.mean, self.good_score.std,
                   self.bad_score.mean, self.bad_score.std)

    ref_score_min = min(self.good_score.mean, self.bad_score.mean)
    ref_score_max = max(self.good_score.mean, self.bad_score.mean)
    success = False
    retry = 3
    for _ in range(retry):
      try:
        splitter = float(cros_build_lib.GetInput(
            'Please give a threshold that tell apart good and bad commit '
            '(within range [%.3f, %.3f]: ' % (ref_score_min, ref_score_max)))
      except ValueError:
        logging.error('Threshold should be a floating number.')
        continue

      if ref_score_min <= splitter <= ref_score_max:
        self.threshold = abs(self.good_score.mean - splitter)
        success = True
        break
      else:
        logging.error('Threshold should be within range [%.3f, %.3f]',
                      ref_score_min, ref_score_max)
    else:
      logging.error('Wrong threshold input for %d times. Terminate.', retry)

    return success

  def BuildDeployEval(self, raise_on_error=True):
    """Builds the image, deploys to DUT and evaluates performance.

    Args:
      raise_on_error: If set, raises Exception if score is unable to get.

    Returns:
      Evaluation result.

    Raises:
      Exception if raise_on_error and score is unable to get.
    """
    self.UpdateCurrentCommit()
    last_score = self.evaluator.CheckLastEvaluate(self.current_commit.sha1,
                                                  self.eval_repeat)
    if len(last_score) > 0:
      self.current_commit.score = last_score
      return last_score

    # TODO(deanliao): handle build/deploy fail case.
    build_to_deploy = self.builder.Build(self.current_commit.sha1)
    self.builder.Deploy(self.remote, build_to_deploy, self.current_commit.sha1)
    score = self.evaluator.Evaluate(self.remote, self.current_commit.sha1,
                                    self.eval_repeat)
    self.current_commit.score = score
    if not score and raise_on_error:
      raise Exception('Unable to obtain evaluation score')
    return score

  def LabelBuild(self, score):
    """Determines if a build is good.

    Args:
      score: evaluation score of the build.

    Returns:
      'good' if the score is closer to given good one; otherwise (including
      score is None), 'bad'.
    """
    label = 'bad'
    if not score:
      logging.error('No score. Marked as bad.')
      return label

    ref_score_min = min(self.good_score.mean, self.bad_score.mean)
    ref_score_max = max(self.good_score.mean, self.bad_score.mean)
    if ref_score_min < score.mean < ref_score_max:
      # Within (good_score, bad_score)
      if abs(self.good_score.mean - score.mean) <= self.threshold:
        label = 'good'
    else:
      dist_good = abs(self.good_score.mean - score.mean)
      dist_bad = abs(self.bad_score.mean - score.mean)
      if dist_good < dist_bad:
        label = 'good'
    logging.info('Score %.3f marked as %s', score.mean, label)
    return label

  def GitBisect(self, bisect_op):
    """Calls git bisect and logs result.

    Args:
      bisect_op: git bisect subcommand list.

    Returns:
      A CommandResult object.
      done: True if bisect ends.
    """
    command = ['bisect'] + bisect_op
    command_str = cros_build_lib.CmdToStr(['git'] + command)
    result = self.Git(command)
    done = False
    log_msg = [command_str]
    if result.output:
      log_msg.append('(output): %s' % result.output.strip())
    if result.error:
      log_msg.append('(error): %s' % result.error.strip())
    if result.returncode != 0:
      log_msg.append('(returncode): %d' % result.returncode)

    log_msg = '\n'.join(log_msg)
    if result.error or result.returncode != 0:
      logging.error(log_msg)
    else:
      logging.info(log_msg)

    if result.output:
      if 'is the first bad commit' in result.output.splitlines()[0]:
        done = True
    return result, done

  def Run(self):
    """Bisects culprit commit.

    Returns:
      Culprit commit's SHA1. None if culprit not found.
    """
    def CommitInfoToStr(info):
      timestamp = datetime.datetime.fromtimestamp(info.timestamp).isoformat(' ')
      score = 'Score(mean: %.3f std: %.3f)' % (info.score.mean, info.score.std)
      return ' '.join([info.label, timestamp, score, info.sha1, info.title])

    (good_commit_info, bad_commit_info) = self.SanityCheck()
    if good_commit_info is None or bad_commit_info is None:
      # logging.error was already called in SanityCheck.
      return None
    if not self.GetThresholdFromUser():
      return None
    self.GitBisect(['reset'])
    bisect_done = False
    culprit_commit = None
    bisect_log = [good_commit_info, bad_commit_info]
    nth_bisect = 0
    try:
      with cros_build_lib.TimedSection() as timer:
        self.GitBisect(['start'])
        self.GitBisect(['bad', self.bad_commit])
        self.GitBisect(['good', self.good_commit])
        while not bisect_done:
          metric_score = self.BuildDeployEval()
          bisect_op = self.LabelBuild(metric_score)
          nth_bisect += 1
          self.current_commit.label = '%2d-th-bisect-%-4s' % (nth_bisect,
                                                              bisect_op)
          bisect_log.append(self.current_commit)
          logging.notice('Mark %s as %s. Score: %s', self.current_commit.sha1,
                         bisect_op, metric_score)
          bisect_result, bisect_done = self.GitBisect([bisect_op])
          if bisect_done:
            culprit_commit = bisect_result.output.splitlines()[1:]
      if bisect_done:
        logging.info('git bisect done. Elapsed time: %s', timer.delta)
    finally:
      self.GitBisect(['log'])
      self.GitBisect(['reset'])

    bisect_log.sort(key=lambda x: x.timestamp)
    logging.notice(
        'Bisect log (sort by time):\n' +
        '\n'.join(map(CommitInfoToStr, bisect_log)))

    if culprit_commit:
      logging.notice('\n'.join(['Culprit commit:'] + culprit_commit))
      # First line: commit <SHA>
      return culprit_commit[0].split()[1]
    else:
      logging.notice('Culprit not found.')
      return None