Add verbose option to binary search tool

Ignore most output from binary search tool and provide option to see full
output with the -V or --verbose option. Full output will still logged even
without the --verbose option.

TEST=Ran binary_search_tool_tester and cros_pkg

Change-Id: I02d958f79813083b48d989c9881536ad025bb1dc
Reviewed-on: https://chrome-internal-review.googlesource.com/264075
Commit-Ready: Cassidy Burden <cburden@google.com>
Tested-by: Cassidy Burden <cburden@google.com>
Reviewed-by: Caroline Tice <cmtice@google.com>
Reviewed-by: Han Shen <shenhan@google.com>

2 files changed, 48 insertions, 25 deletions

diff --git a/binary_search_tool/binary_search_perforce.py b/binary_search_tool/binary_search_perforce.py
index 5e58223d..39da8e2b 100755
--- a/binary_search_tool/binary_search_perforce.py
+++ b/binary_search_tool/binary_search_perforce.py
@@ -12,6 +12,8 @@ import tempfile
 from cros_utils import command_executer
 from cros_utils import logger
 
+verbose = True
+
 def _GetP4ClientSpec(client_name, p4_paths):
   p4_string = ""
   for p4_path in p4_paths:
@@ -87,7 +89,7 @@ class BinarySearcher(object):
                (self.sorted_list[self.current],
                 self.current,
                 status))
-    logger.GetLogger().LogOutput(message)
+    logger.GetLogger().LogOutput(message, print_to_console=verbose)
     assert status == 0 or status == 1 or status == 2
     self.index_log.append(self.current)
     self.status_log.append(status)
@@ -117,7 +119,8 @@ class BinarySearcher(object):
       if index not in self.skipped_indices:
         return False
     logger.GetLogger().LogOutput(
-        "All skipped indices between: %d and %d\n" % (self.lo, self.hi))
+        "All skipped indices between: %d and %d\n" % (self.lo, self.hi),
+        print_to_console=verbose)
     return True
 
   # Does a better job with chromeos flakiness.
@@ -164,12 +167,12 @@ class BinarySearcher(object):
     message = ("Estimated tries: min: %d max: %d\n" %
                (1 + math.log(self.hi - self.lo, 2),
                 self.hi - self.lo - len(self.skipped_indices)))
-    logger.GetLogger().LogOutput(message)
+    logger.GetLogger().LogOutput(message, print_to_console=verbose)
     message = ("lo: %d hi: %d current: %d version: %s\n" %
                (self.lo, self.hi, self.current,
                 self.sorted_list[self.current]))
-    logger.GetLogger().LogOutput(message)
-    logger.GetLogger().LogOutput(str(self))
+    logger.GetLogger().LogOutput(message, print_to_console=verbose)
+    logger.GetLogger().LogOutput(str(self), print_to_console=verbose)
     return self.sorted_list[self.current]
 
   def SetLoRevision(self, lo_revision):
@@ -405,18 +408,21 @@ def Main(argv):
       status = ce.RunCommand(command)
       message = ("Revision: %s produced: %d status\n" %
                  (current_revision, status))
-      logger.GetLogger().LogOutput(message)
+      logger.GetLogger().LogOutput(message, print_to_console=verbose)
       terminated = p4gccbs.SetStatus(status)
       num_tries -= 1
-      logger.GetLogger().LogOutput(str(p4gccbs))
+      logger.GetLogger().LogOutput(str(p4gccbs), print_to_console=verbose)
 
     if not terminated:
-      logger.GetLogger().LogOutput("Tries: %d expired." % num_tries)
-    logger.GetLogger().LogOutput(str(p4gccbs.bs))
+      logger.GetLogger().LogOutput("Tries: %d expired." % num_tries,
+                                   print_to_console=verbose)
+    logger.GetLogger().LogOutput(str(p4gccbs.bs),
+                                 print_to_console=verbose)
   except (KeyboardInterrupt, SystemExit):
     logger.GetLogger().LogOutput("Cleaning up...")
   finally:
-    logger.GetLogger().LogOutput(str(p4gccbs.bs))
+    logger.GetLogger().LogOutput(str(p4gccbs.bs),
+                                 print_to_console=verbose)
     status = p4gccbs.Cleanup()
 
 
diff --git a/binary_search_tool/binary_search_state.py b/binary_search_tool/binary_search_state.py
index 56eaee10..e6fe38e9 100755
--- a/binary_search_tool/binary_search_state.py
+++ b/binary_search_tool/binary_search_state.py
@@ -32,7 +32,7 @@ class BinarySearchState(object):
 
   def __init__(self, get_initial_items, switch_to_good, switch_to_bad,
                install_script, test_script, incremental, prune, iterations,
-               prune_iterations, verify_level, file_args):
+               prune_iterations, verify_level, file_args, verbose):
     self.get_initial_items = get_initial_items
     self.switch_to_good = switch_to_good
     self.switch_to_bad = switch_to_bad
@@ -44,6 +44,7 @@ class BinarySearchState(object):
     self.prune_iterations = prune_iterations
     self.verify_level = verify_level
     self.file_args = file_args
+    self.verbose = verbose
 
     self.l = logger.GetLogger()
     self.ce = command_executer.GetCommandExecuter()
@@ -57,18 +58,19 @@ class BinarySearchState(object):
   def SwitchToGood(self, item_list):
     if self.incremental:
       self.l.LogOutput('Incremental set. Wanted to switch %s to good' %
-                       str(item_list))
+                       str(item_list), print_to_console=self.verbose)
       incremental_items = [
           item for item in item_list if item not in self.currently_good_items
       ]
       item_list = incremental_items
       self.l.LogOutput('Incremental set. Actually switching %s to good' %
-                       str(item_list))
+                       str(item_list), print_to_console=self.verbose)
 
     if not item_list:
       return
 
-    self.l.LogOutput('Switching %s to good' % str(item_list))
+    self.l.LogOutput('Switching %s to good' % str(item_list),
+                     print_to_console=self.verbose)
     self.RunSwitchScript(self.switch_to_good, item_list)
     self.currently_good_items = self.currently_good_items.union(set(item_list))
     self.currently_bad_items.difference_update(set(item_list))
@@ -76,18 +78,19 @@ class BinarySearchState(object):
   def SwitchToBad(self, item_list):
     if self.incremental:
       self.l.LogOutput('Incremental set. Wanted to switch %s to bad' %
-                       str(item_list))
+                       str(item_list), print_to_console=self.verbose)
       incremental_items = [
           item for item in item_list if item not in self.currently_bad_items
       ]
       item_list = incremental_items
       self.l.LogOutput('Incremental set. Actually switching %s to bad' %
-                       str(item_list))
+                       str(item_list), print_to_console=self.verbose)
 
     if not item_list:
       return
 
-    self.l.LogOutput('Switching %s to bad' % str(item_list))
+    self.l.LogOutput('Switching %s to bad' % str(item_list),
+                     print_to_console=self.verbose)
     self.RunSwitchScript(self.switch_to_bad, item_list)
     self.currently_bad_items = self.currently_bad_items.union(set(item_list))
     self.currently_good_items.difference_update(set(item_list))
@@ -101,7 +104,7 @@ class BinarySearchState(object):
       command = '%s %s' % (switch_script, temp_file)
     else:
       command = '%s %s' % (switch_script, ' '.join(item_list))
-    ret = self.ce.RunCommand(command)
+    ret = self.ce.RunCommand(command, print_to_console=self.verbose)
     assert ret == 0, 'Switch script %s returned %d' % (switch_script, ret)
 
   def TestScript(self):
@@ -170,7 +173,8 @@ class BinarySearchState(object):
         new_all_items = new_all_items[prune_index - 1:]
 
       self.l.LogOutput('Old list: %s. New list: %s' % (str(self.all_items),
-                                                       str(new_all_items)))
+                                                       str(new_all_items)),
+                       print_to_console=self.verbose)
 
       # FIXME: Do we need to Convert the currently good items to bad
       self.PopulateItemsUsingList(new_all_items)
@@ -197,12 +201,12 @@ class BinarySearchState(object):
         self.l.LogOutput('Terminated!')
     if not terminated:
       self.l.LogOutput('Ran out of iterations searching...')
-    self.l.LogOutput(str(self))
+    self.l.LogOutput(str(self), print_to_console=self.verbose)
     return terminated
 
   def PopulateItemsUsingCommand(self, command):
     ce = command_executer.GetCommandExecuter()
-    _, out, _ = ce.RunCommandWOutput(command)
+    _, out, _ = ce.RunCommandWOutput(command, print_to_console=self.verbose)
     all_items = out.split()
     self.PopulateItemsUsingList(all_items)
 
@@ -263,15 +267,21 @@ def Main(argv):
   parser.add_argument('-i',
                       '--get_initial_items',
                       dest='get_initial_items',
-                      help='Script to run to get the initial objects.')
+                      help=('Script to run to get the initial objects. '
+                            'If your script requires user input '
+                            'the --verbose option must be used'))
   parser.add_argument('-g',
                       '--switch_to_good',
                       dest='switch_to_good',
-                      help='Script to run to switch to good.')
+                      help=('Script to run to switch to good. '
+                            'If your switch script requires user input '
+                            'the --verbose option must be used'))
   parser.add_argument('-b',
                       '--switch_to_bad',
                       dest='switch_to_bad',
-                      help='Script to run to switch to bad.')
+                      help=('Script to run to switch to bad. '
+                            'If your switch script requires user input '
+                            'the --verbose option must be used'))
   parser.add_argument('-I',
                       '--install_script',
                       dest='install_script',
@@ -313,6 +323,11 @@ def Main(argv):
                       dest='prune_iterations',
                       help='Number of prune iterations to try in the search.',
                       default=100)
+  parser.add_argument('-V',
+                      '--verbose',
+                      dest='verbose',
+                      action='store_true',
+                      help='Print full output to console.')
 
   logger.GetLogger().LogOutput(' '.join(argv))
   options = parser.parse_args(argv)
@@ -334,6 +349,8 @@ def Main(argv):
   prune_iterations = options.prune_iterations
   verify_level = options.verify_level
   file_args = options.file_args
+  verbose = options.verbose
+  binary_search_perforce.verbose = verbose
 
   if options.noincremental:
     incremental = False
@@ -344,7 +361,7 @@ def Main(argv):
     bss = BinarySearchState(get_initial_items, switch_to_good, switch_to_bad,
                             install_script, test_script, incremental, prune,
                             iterations, prune_iterations, verify_level,
-                            file_args)
+                            file_args, verbose)
     bss.DoVerify()
     bss.DoSearch()