Move probe() from hwid_tool into gooftool.

Since probe only makes sense on a DUT, and since probing requires
modules only available on DUTs, the probe command does not belong
in hwid_tool.

As part of the move, clean up the code a bit.

The output of probe should be tolerably human-readable, but
primarily machine parseable.  This CL cleans things up to only
use yaml-encoded output.

Probe result cooking is cleaned up as well.

BUG=chrome-os-partner:8616
TEST=run gooftool --probe and --verify-hwid

Change-Id: I1fe9382cbb25dd94b2d8a31f66158ed03f773255
Reviewed-on: https://gerrit.chromium.org/gerrit/18950
Commit-Ready: Tammo Spalink <tammo@chromium.org>
Reviewed-by: Tammo Spalink <tammo@chromium.org>
Tested-by: Tammo Spalink <tammo@chromium.org>
diff --git a/common.py b/common.py
index 5d24190..c914881 100644
--- a/common.py
+++ b/common.py
@@ -7,6 +7,7 @@
 
 import logging
 import re
+import time
 
 from subprocess import Popen, PIPE
 
@@ -58,3 +59,19 @@
   if isinstance(data, list) or isinstance(data, tuple):
     data = ' '.join(x for x in data if x != '')
   return re.sub('\s+', ' ', data).strip()
+
+
+def SetupLogging(level=logging.WARNING, log_file_name=None):
+  """Configure logging level, format, and target file/stream.
+
+  Args:
+    level: The logging.{DEBUG,INFO,etc} level of verbosity to show.
+    log_file_name: File for appending log data.
+  """
+  logging.basicConfig(
+      format='%(levelname)-8s %(asctime)-8s %(message)s',
+      datefmt='%H:%M:%S',
+      level=level,
+      **({'filename': log_file_name} if log_file_name else {}))
+  logging.Formatter.converter = time.gmtime
+  logging.info(time.strftime('%Y.%m.%d %Z', time.gmtime()))
diff --git a/gft_report.py b/gft_report.py
index 930439f..61acb6b 100755
--- a/gft_report.py
+++ b/gft_report.py
@@ -39,7 +39,7 @@
 
 
 # Update this if any field names (or formats) have been changed.
-REPORT_VERSION = 3
+REPORT_VERSION = 4
 
 # Keys in decoding results
 KEY_INFO_DECODERS = 'decoders'
@@ -155,9 +155,7 @@
                            ]
   mandatory_dict_keys = ['crossystem',
                          'hwid_properties',
-                         'probe_results',
-                         'cooked_device_details',
-                         'cooked_components',
+                         'cooked_probe_results',
                          'ro_vpd',
                          'rw_vpd',
                          ]
@@ -269,10 +267,7 @@
 
   # HWID-related Device Data
   report['hwid_properties'] = system_details.hwid_properties.__dict__
-  report['probe_results'] = system_details.probe_results.__dict__
-  report['cooked_components'] = system_details.cooked_components.__dict__
-  report['cooked_device_details'] = (
-      system_details.cooked_device_details.__dict__)
+  report['cooked_probe_results'] = system_details.cooked_results.__dict__
 
   # Firmware write protection status
   # TODO(hungte) Replace by crosfw.Flashrom.
diff --git a/gooftool b/gooftool
index 481560a..f7bc2a7 100755
--- a/gooftool
+++ b/gooftool
@@ -15,11 +15,13 @@
 
 import copy
 import glob
+import logging
 import optparse
 import os
 import re
 import sys
 import tempfile
+import yaml
 
 ########################################################################
 # cros/gft modules
@@ -34,7 +36,7 @@
 import hwid_tool
 import probe
 
-from common import Obj
+from common import Obj, SetupLogging
 from gft_common import WarningMsg, VerboseMsg, DebugMsg, ErrorMsg, ErrorDie
 
 
@@ -189,6 +191,15 @@
 
 
 @GFTCommand
+def run_probe():
+  """Print yaml-formatted breakdown of probed device properties."""
+  SetupLogging(logging.DEBUG, g_options.probe_log)
+  probe_results = probe.Probe()
+  print yaml.dump(probe_results.__dict__, default_flow_style=False)
+  return True
+
+
+@GFTCommand
 def verify_hwid():
   """Verify system HWID properties match probed device properties.
 
@@ -199,58 +210,54 @@
   those specified for its HWID.
   """
   main_fw_file = crosfw.LoadMainFirmware().path
-  gbb_result = gft_common.SystemOutput('gbb_utility -g --hwid %s' %
-                                       main_fw_file)
+  gbb_result = gft_common.SystemOutput(
+      'gbb_utility -g --hwid %s' % main_fw_file)
   hwid = re.findall(r'hardware_id:(.*)', gbb_result)[0].strip()
   DebugMsg('system HWID: %r\n' % hwid)
   try:
     data = hwid_tool.ReadDatastore(g_options.db_path)
     hwid_properties = hwid_tool.LookupHwidProperties(data, hwid)
-    DebugMsg('expected system properties: %s' % hwid_properties.__dict__)
+    board = hwid_properties.board
+    DebugMsg('expected system properties:\n%s' %
+             yaml.dump(hwid_properties.__dict__, default_flow_style=False))
     probe_results = probe.Probe()
-    DebugMsg('found system properties: %s' % probe_results.__dict__)
-    cooked_components = hwid_tool.CookComponentProbeResults(
-        data.comp_db, probe_results)
-    DebugMsg('cooked components: %s' % cooked_components.__dict__)
-    device = data.device_db[hwid_properties.board]
-    cooked_device_details = hwid_tool.CookDeviceProbeResults(
-        device, probe_results)
-    DebugMsg('cooked device details: %s' % cooked_device_details.__dict__)
+    cooked_results = hwid_tool.CookProbeResults(data, probe_results, board)
+    DebugMsg('found system properties:\n%s' %
+             yaml.dump(cooked_results.__dict__, default_flow_style=False))
     global g_cached_device_data
     g_cached_device_data = Obj(
         hwid_properties=hwid_properties,
-        probe_results=probe_results,
-        cooked_components=cooked_components,
-        cooked_device_details=cooked_device_details)
+        cooked_results=cooked_results)
   except hwid_tool.Error, e:
     ErrorDie('verify_hwid: FAILED.\n%s' % e)
   match_errors = []
-  for comp_class, comp_value in hwid_properties.component_map.items():
-    if comp_value == 'ANY':
+  for comp_class, expected_name in hwid_properties.component_map.items():
+    if expected_name == 'ANY':
       continue
-    found_value = cooked_components.known.get(comp_class, None)
-    if found_value != comp_value:
-      if found_value is None:
-        alt_value = cooked_components.unknown.get(comp_class, None)
-        found_value = 'UNKNOWN %r' % alt_value
-      match_errors.append('  %s component mismatch, expected %s, found %s' %
-                          (comp_class, comp_value, found_value))
+    if expected_name == cooked_results.matched_components.get(comp_class, None):
+      continue
+    if comp_class in probe_results.missing_components:
+      match_errors.append('  %s component mismatch, expected %s, found nothing'
+                          % (comp_class, expected_name))
+    else:
+      probe_value = probe_results.found_components.get(comp_class, None)
+      match_errors.append('  %s component mismatch, expected %s, found  %r' %
+                          (comp_class, expected_name, probe_value))
   if match_errors:
     ErrorDie('verify_hwid: FAILED.\n%s' % '\n'.join(match_errors))
-  if hwid_properties.volatile not in cooked_device_details.volatile_set:
+  if hwid_properties.volatile not in cooked_results.matched_volatile_tags:
     msg = ('  HWID specified volatile %s, but found match only for %s' %
            (hwid_properties.volatile,
-            ', '.join(cooked_device_details.volatile_set)))
+            ', '.join(cooked_results.matched_volatile_tags)))
     ErrorDie('verify_hwid: FAILED.\n%s' % msg)
   if (hwid_properties.initial_config is not None and
       hwid_properties.initial_config not in
-      cooked_device_details.initial_config_set):
+      cooked_results.matched_initial_config_tags):
     msg = ('  HWID specified initial_config %s, but found match only for %s' %
            (hwid_properties.initial_config,
-            ', '.join(cooked_device_details.initial_config_set)))
+            ', '.join(cooked_results.matched_initial_config_tags)))
     ErrorDie('verify_hwid: FAILED.\n%s' % msg)
   # TODO(tammo): Verify HWID status is supported (or deprecated for RMA).
-  # TODO(tammo): Verify release string.
   # TODO(tammo): Verify VPD here, using hwid_properties.vpd_ro_field_list.
   print 'Verified: %s' % hwid
   return True
@@ -523,6 +530,10 @@
   parser.add_option('--log_path', metavar='PATH',
                     default=gft_common.DEFAULT_CONSOLE_LOG_PATH,
                     help='use the given path for verbose logs.')
+  # TODO(tammo): Remove this when gooftool converts to use logging module.
+  parser.add_option('--probe_log', metavar='PATH',
+                    default='/var/log/factory_probe.log',
+                    help='probe process details')
   # Debugging
   parser.add_option('--debug_dryrun_wpfw', action='store_true',
                     help='make --wpfw in dry-run mode (debugging only)')
diff --git a/hwid_tool.py b/hwid_tool.py
index cbe07e1..7dccc79 100755
--- a/hwid_tool.py
+++ b/hwid_tool.py
@@ -3,7 +3,6 @@
 # Use of this source code is governed by a BSD-style license that can be
 # found in the LICENSE file.
 
-from argparse import ArgumentParser
 
 import difflib
 import logging
@@ -12,10 +11,10 @@
 import re
 import string
 import sys
-import time
 import zlib
 
-from common import Error, Obj
+from argparse import ArgumentParser, Action
+from common import Error, Obj, SetupLogging
 from bom_names import BOM_NAME_SET
 from hwid_database import InvalidDataError, MakeDatastoreSubclass
 from hwid_database import YamlWrite, YamlRead
@@ -65,6 +64,10 @@
     })
 
 
+# TODO(tammo): Maintain the invariant that the set of component
+# classes in the component_db matches the set of component classes in
+# all boms, and also matches the set output by the probing code.
+
 # TODO(tammo): Variant data should have 'probe results' stored in the
 # component_db, and the variant_map should only contain a list of
 # canonical component names.  Based on the component classes that
@@ -528,38 +531,42 @@
           if ComponentConfigStr(comp_map) not in existing_comp_map_str_set]
 
 
-def CookComponentProbeResults(comp_db, probe_results):
-  """TODO(tammo): Add more here XXX."""
-  match = Obj(known={}, unknown={})
-  comp_reference_map = CalcCompDbProbeValMap(comp_db)
+def CookProbeResults(data, probe_results, board_name):
+  """Correlate probe results with component and board data.
+
+  For components, return a comp_class:comp_name dict for matches.  For
+  volatile and initial_config, return corresponding sets of index
+  values where the index values correspond to existing board data that
+  matches the probe results.
+  """
+  results = Obj(
+      matched_components={},
+      matched_volatiles=[],
+      matched_volatile_tags=[],
+      matched_initial_config_tags=[])
+  results.__dict__.update(probe_results.__dict__)
+  comp_reference_map = CalcCompDbProbeValMap(data.comp_db)
   for probe_class, probe_value in probe_results.found_components.items():
-    if probe_value is None:
-      continue
     if probe_value in comp_reference_map:
-      match.known[probe_class] = comp_reference_map[probe_value]
-    else:
-      match.unknown[probe_class] = probe_value
-  return match
-
-
-def CookDeviceProbeResults(device, probe_results):
-  """TODO(tammo): Add more here XXX."""
-  match = Obj(volatile_set=set(), initial_config_set=set())
-  # TODO(tammo): Precompute this reverse map.
-  volatile_reference_map = dict((v, c) for c, v in
-                                device.volatile_value_map.items())
-  vol_map = dict((c, volatile_reference_map[v])
-                 for c, v in probe_results.volatiles.items()
-                 if v in volatile_reference_map)
-  for volatile, vol_reference_map in device.volatile_map.items():
-    if all(vol_reference_map[c] == v for c, v in vol_map.items()
-           if vol_reference_map[c] != 'ANY'):
-      match.volatile_set.add(volatile)
-  for initial_config, ic_map in device.initial_config_map.items():
-    if all(probe_results.initial_configs.get(ic_class, None) != ic_value
-           for ic_class, ic_value in ic_map.items()):
-      match.initial_config_set.add(initial_config)
-  return match
+      results.matched_components[probe_class] = comp_reference_map[probe_value]
+  device = data.device_db[board_name]
+  volatile_reference_map = dict(
+      (v, c) for c, v in device.volatile_value_map.items())
+  results.matched_volatiles = dict(
+      (c, volatile_reference_map[v])
+      for c, v in probe_results.volatiles.items()
+      if v in volatile_reference_map)
+  for volatile_tag, volatile_map in device.volatile_map.items():
+    if (all(results.matched_volatiles.get(c, None) == v
+            for c, v in volatile_map.items())
+        and volatile_tag not in results.matched_volatile_tags):
+      results.matched_volatile_tags.append(volatile_tag)
+  for initial_config_tag, ic_map in device.initial_config_map.items():
+    if (all(probe_results.initial_configs.get(ic_class, None) == ic_value
+           for ic_class, ic_value in ic_map.items())
+        and initial_config_tag not in results.matched_initial_config_tags):
+      results.matched_initial_config_tags.append(initial_config_tag)
+  return results
 
 
 def LookupHwidProperties(data, hwid):
@@ -724,52 +731,6 @@
       IndentedStructuredPrint(0, comp_class + ':', comp_map)
 
 
-@Command('probe_device',
-         CmdArg('-b', '--board'),
-         CmdArg('-c', '--classes', nargs='*'),
-         CmdArg('-r', '--raw', action='store_true'))
-def ProbeDeviceProperties(config, data):
-  # TODO(tammo): Implement classes arg behavior.
-  # TODO(tammo): Move this command into gooftool to avoid having to
-  # load the probe module here. The probe module depends on other
-  # modules that are not available except on DUT machines.
-  from probe import Probe
-  probe_results = Probe()
-  if config.raw:
-    print YamlWrite(probe_results.__dict__)
-    return
-  IndentedStructuredPrint(0, 'component probe results:',
-                          probe_results.found_components)
-  IndentedStructuredPrint(0, 'missing components (no results):',
-                          probe_results.missing_components)
-  missing_classes = (set(data.comp_db.registry) -
-                     set(probe_results.found_components))
-  if missing_classes:
-    logging.warning('missing information for comp classes: %s' %
-                    ', '.join(missing_classes))
-
-  cooked_components = CookComponentProbeResults(data.comp_db, probe_results)
-  if cooked_components.known:
-    IndentedStructuredPrint(0, 'known components:', cooked_components.known)
-  if cooked_components.unknown:
-    IndentedStructuredPrint(0, 'unknown components:', cooked_components.unknown)
-  if config.board:
-    if config.board not in data.device_db:
-      logging.critical('unknown board %r (known boards: %s' %
-                       (config.board, ', '.join(sorted(data.device_db))))
-      return
-    device = data.device_db[config.board]
-    cooked_device_details = CookDeviceProbeResults(device, probe_results)
-    IndentedStructuredPrint(0, 'volatile probe results:',
-                            probe_results.volatiles)
-    IndentedStructuredPrint(0, 'matching volatile tags:',
-                            cooked_device_details.volatile_set)
-    IndentedStructuredPrint(0, 'initial_config probe results:',
-                            probe_results.initial_configs)
-    IndentedStructuredPrint(0, 'matching initial_config tags:',
-                            cooked_device_details.initial_config_set)
-
-
 @Command('assimilate_probe_data',
          CmdArg('-b', '--board'),
          CmdArg('--bom'))
@@ -798,6 +759,7 @@
   the input data.
   """
   probe_results = Obj(**YamlRead(sys.stdin.read()))
+  # TODO(tammo): Refactor to use CookProbeResults.
   components = getattr(probe_results, 'found_components', {})
   registry = data.comp_db.registry
   if not set(components) <= set(registry):
@@ -847,7 +809,6 @@
       volatile_name = '%s_%d' % (volatile_class, len(device.volatile_value_map))
       device.volatile_value_map[volatile_name] = probe_value
       volatile_match_dict[volatile_class] = volatile_name
-  volatile_match_index = None
   for volatile_index, volatile in device.volatile_map.items():
     if volatile_match_dict == volatile:
       volatile_match_index = volatile_index
@@ -858,7 +819,6 @@
     device.volatile_map[volatile_match_index] = volatile_match_dict
     print 'added volatile: %r' % volatile_match_index
   probe_initial_config = getattr(probe_results, 'initial_configs', {})
-  initial_config_match_index = None
   for initial_config_index, initial_config in device.initial_config_map.items():
     if probe_initial_config == initial_config:
       initial_config_match_index = initial_config_index
@@ -1120,7 +1080,13 @@
       description='Visualize and/or modify HWID and related component data.')
   parser.add_argument('-p', '--data_path', metavar='PATH',
                       default=DEFAULT_HWID_DATA_PATH)
-  parser.add_argument('-v', '--verbosity', choices='01234', default='2')
+  class VerbosityAction(Action):
+    def __call__(self, parser, namespace, values, option_string=None):
+      logging_level = {4: logging.DEBUG, 3: logging.INFO, 2: logging.WARNING,
+                       1: logging.ERROR, 0: logging.CRITICAL}[int(values)]
+      setattr(namespace, self.dest, logging_level)
+  parser.add_argument('-v', '--verbosity', choices='01234', default='2',
+                      action=VerbosityAction)
   parser.add_argument('-l', '--log_file')
   subparsers = parser.add_subparsers(dest='command_name')
   for cmd_name, (fun, doc, arg_list) in G_commands.items():
@@ -1131,22 +1097,10 @@
   return parser.parse_args()
 
 
-def SetupLogging(config):
-  """Configure logging level, format, and target file/stream."""
-  logging.basicConfig(
-      format='%(levelname)-8s %(asctime)-8s %(message)s',
-      datefmt='%H:%M:%S',
-      level={4: logging.DEBUG, 3: logging.INFO, 2: logging.WARNING,
-             1: logging.ERROR, 0: logging.CRITICAL}[int(config.verbosity)],
-      **({'filename': config.log_file} if config.log_file else {}))
-  logging.Formatter.converter = time.gmtime
-  logging.info(time.strftime('%Y.%m.%d %Z', time.gmtime()))
-
-
 def Main():
   """Run sub-command specified by the command line args."""
   config = ParseCmdline()
-  SetupLogging(config)
+  SetupLogging(config.verbosity, config.log_file)
   data = ReadDatastore(config.data_path)
   try:
     config.command(config, data)
diff --git a/probe.py b/probe.py
index 84e9928..bbd3d1e 100644
--- a/probe.py
+++ b/probe.py
@@ -789,17 +789,18 @@
       logging.exception('Probe FAILED (%s), see traceback, returning None.' %
                         fun.__name__)
       return None
-  component_result_map = {}
-  hash_result_map = {}
-  initial_config_result_map = {}
-  missing_component_list = []
+  results = Obj(
+      found_components={},
+      missing_components=[],
+      volatiles={},
+      initial_configs={})
   for component_class, fun_data in sorted(_COMPONENT_PROBE_MAP.items()):
     fun = fun_data[arch] if isinstance(fun_data, dict) else fun_data
-    result = RunProbe(fun)
-    if result is not None:
-      component_result_map[component_class] = result
+    probe_value = RunProbe(fun)
+    if probe_value is not None:
+      results.found_components[component_class] = probe_value
     else:
-      missing_component_list.append(component_class)
+      results.missing_components.append(component_class)
   if probe_volatile:
     # TODO(tammo): Lift out the hash generation, to allow convenient
     # generation of hashes directly for firmware images (as opposed to
@@ -810,15 +811,11 @@
     # probing for new BOM components, should help with appending new
     # hash values to the database.
     for hash_class, fun in sorted(_HASH_PROBE_MAP.items()):
-      hash_result_map[hash_class] = RunProbe(fun)
-  else:
-    hash_result_map = None
+      results.volatiles[hash_class] = RunProbe(fun)
   if probe_initial_config:
     for initial_config_class, fun in sorted(_INITIAL_CONFIG_PROBE_MAP.items()):
-      initial_config_result_map[initial_config_class] = RunProbe(fun)
-  else:
-    initial_config_result_map = None
-  return Obj(found_components=component_result_map,
-             missing_components=missing_component_list,
-             volatiles=hash_result_map,
-             initial_configs=initial_config_result_map)
+      probe_value = RunProbe(fun)
+      # TODO(tammo): Remove this conversion once initial_config is improved.
+      probe_value = '' if probe_value is None else probe_value
+      results.initial_configs[initial_config_class] = probe_value
+  return results